Add diagnostics to the processor component (#3087)

This change adds the same diagnostics event to the `IConfigurationSetProcessorFactory` as the `ConfigurationProcessor` already has. It also adds a property to control the minimum level of events, enabling filtering to be done at event publishing rather than consumption. All of the public facing methods in the processor component are enlightened to send any escaping exceptions to the diagnostics before letting them generate an error. Additionally, verbose logs are added throughout to enable a better understanding of what/when things are happening.
microsoft · Mar 21, 2023 · 1898da0 · 1898da0
1 parent bfcee8e
commit 1898da0
Show file tree

Hide file tree

Showing 24 changed files with 418 additions and 120 deletions.
diff --git a/src/AppInstallerCLICore/ConfigurationSetProcessorFactoryRemoting.cpp b/src/AppInstallerCLICore/ConfigurationSetProcessorFactoryRemoting.cpp
@@ -3,6 +3,7 @@
 #include "pch.h"
 #include "ConfigurationSetProcessorFactoryRemoting.h"
 
+using namespace winrt::Windows::Foundation;
 using namespace winrt::Microsoft::Management::Configuration;
 
 namespace AppInstaller::CLI::Workflow::ConfigurationRemoting
@@ -38,6 +39,8 @@ namespace AppInstaller::CLI::Workflow::ConfigurationRemoting
         {
             RemoteFactory()
             {
+                AICLI_LOG(Config, Verbose, << "Launching process for configuration processing...");
+
                 // Security attributes to set handles as inherited.
                 SECURITY_ATTRIBUTES securityAttributes{};
                 securityAttributes.nLength = sizeof(securityAttributes);
@@ -75,6 +78,7 @@ namespace AppInstaller::CLI::Workflow::ConfigurationRemoting
                 wil::unique_process_information processInformation;
 
                 THROW_IF_WIN32_BOOL_FALSE(CreateProcessW(serverPath.c_str(), &arguments[0], nullptr, nullptr, TRUE, DETACHED_PROCESS, nullptr, nullptr, &startupInfo, &processInformation));
+                AICLI_LOG(Config, Verbose, << "  Configuration remote PID is " << processInformation.dwProcessId);
 
                 HANDLE waitHandles[2];
                 waitHandles[0] = initEvent.get();
@@ -123,8 +127,9 @@ namespace AppInstaller::CLI::Workflow::ConfigurationRemoting
                 THROW_IF_FAILED(stream->Write(mappedMemory->FactoryObject, mappedMemory->FactorySize, nullptr));
                 THROW_IF_FAILED(stream->Seek({}, STREAM_SEEK_SET, nullptr));
 
-                wil::com_ptr<IUnknown> output;
+                wil::com_ptr<::IUnknown> output;
                 THROW_IF_FAILED(CoUnmarshalInterface(stream.get(), winrt::guid_of<IConfigurationSetProcessorFactory>(), reinterpret_cast<void**>(&output)));
+                AICLI_LOG(Config, Verbose, << "... configuration processing connection established.");
                 m_remoteFactory = IConfigurationSetProcessorFactory{ output.detach(), winrt::take_ownership_from_abi };
             }
 
@@ -133,6 +138,26 @@ namespace AppInstaller::CLI::Workflow::ConfigurationRemoting
                 return m_remoteFactory.CreateSetProcessor(configurationSet);
             }
 
+            winrt::event_token Diagnostics(const EventHandler<DiagnosticInformation>& handler)
+            {
+                return m_remoteFactory.Diagnostics(handler);
+            }
+
+            void Diagnostics(const winrt::event_token& token) noexcept
+            {
+                m_remoteFactory.Diagnostics(token);
+            }
+
+            DiagnosticLevel MinimumLevel()
+            {
+                return m_remoteFactory.MinimumLevel();
+            }
+
+            void MinimumLevel(DiagnosticLevel value)
+            {
+                m_remoteFactory.MinimumLevel(value);
+            }
+
         private:
             IConfigurationSetProcessorFactory m_remoteFactory;
             wil::unique_mutex m_completionMutex;
@@ -163,7 +188,7 @@ HRESULT WindowsPackageManagerConfigurationCompleteOutOfProcessFactoryInitializat
         wil::com_ptr<IStream> stream;
         RETURN_IF_FAILED(CreateStreamOnHGlobal(nullptr, TRUE, &stream));
 
-        RETURN_IF_FAILED(CoMarshalInterface(stream.get(), winrt::guid_of<IConfigurationSetProcessorFactory>(), reinterpret_cast<IUnknown*>(factory), MSHCTX_LOCAL, nullptr, MSHLFLAGS_NORMAL));
+        RETURN_IF_FAILED(CoMarshalInterface(stream.get(), winrt::guid_of<IConfigurationSetProcessorFactory>(), reinterpret_cast<::IUnknown*>(factory), MSHCTX_LOCAL, nullptr, MSHLFLAGS_NORMAL));
 
         ULARGE_INTEGER streamSize{};
         RETURN_IF_FAILED(stream->Seek({}, STREAM_SEEK_CUR, &streamSize));

diff --git a/src/AppInstallerCLICore/Workflows/ConfigurationFlow.cpp b/src/AppInstallerCLICore/Workflows/ConfigurationFlow.cpp
@@ -43,6 +43,20 @@ namespace AppInstaller::CLI::Workflow
             return Logging::Level::Info;
         }
 
+        DiagnosticLevel ConvertLevel(Logging::Level level)
+        {
+            switch (level)
+            {
+            case Logging::Level::Verbose: return DiagnosticLevel::Verbose;
+            case Logging::Level::Info: return DiagnosticLevel::Informational;
+            case Logging::Level::Warning: return DiagnosticLevel::Warning;
+            case Logging::Level::Error: return DiagnosticLevel::Error;
+            case Logging::Level::Crit: return DiagnosticLevel::Critical;
+            }
+
+            return DiagnosticLevel::Informational;
+        }
+
         Resource::StringId ToResource(ConfigurationUnitIntent intent)
         {
             switch (intent)
@@ -102,7 +116,7 @@ namespace AppInstaller::CLI::Workflow
                         break;
                     default:
                         // TODO: Sort out how we actually want to handle this given that we don't expect anything but strings
-                        out << " [PropertyType="_liv << property.Type() << "]\n"_liv;
+                        out << " [Debug:PropertyType="_liv << property.Type() << "]\n"_liv;
                         break;
                     }
                 }
@@ -337,6 +351,7 @@ namespace AppInstaller::CLI::Workflow
                     {
                         AICLI_LOG(Config, Error, << "Configuration unit " << Utility::ConvertToUTF8(unit.UnitName()) << "[" << Utility::ConvertToUTF8(unit.Identifier()) << "] failed with code 0x"
                             << Logging::SetHRFormat << resultInformation.ResultCode() << " and error message:\n" << Utility::ConvertToUTF8(resultInformation.Description()));
+                        // TODO: Improve error reporting for failures: use message, known HRs, getting HR system string, etc.
                         m_context.Reporter.Error() << "  "_liv << Resource::String::ConfigurationUnitFailed << " 0x"_liv << Logging::SetHRFormat << resultInformation.ResultCode() << std::endl;
                     }
                     OutputUnitCompletionProgress();
@@ -383,6 +398,9 @@ namespace AppInstaller::CLI::Workflow
     {
         ConfigurationProcessor processor{ CreateConfigurationSetProcessorFactory() };
 
+        // Set the processor to the current level of the logging.
+        processor.MinimumLevel(ConvertLevel(Logging::Log().GetLevel()));
+
         // Route the configuration diagnostics into the context's diagnostics logging
         processor.Diagnostics([&context](const winrt::Windows::Foundation::IInspectable&, const DiagnosticInformation& diagnostics)
             {
@@ -429,7 +447,15 @@ namespace AppInstaller::CLI::Workflow
             AICLI_TERMINATE_CONTEXT(openResult.ResultCode());
         }
 
-        context.Get<Data::ConfigurationContext>().Set(openResult.Set());
+        ConfigurationSet result = openResult.Set();
+
+        // Fill out the information about the set based on it coming from a file.
+        // TODO: Consider how to properly determine a good value for name and origin.
+        result.Name(absolutePath.filename().wstring());
+        result.Origin(absolutePath.parent_path().wstring());
+        result.Path(absolutePath.wstring());
+
+        context.Get<Data::ConfigurationContext>().Set(result);
     }
 
     void ShowConfigurationSet(Context& context)

diff --git a/src/AppInstallerCLITests/TestConfiguration.cpp b/src/AppInstallerCLITests/TestConfiguration.cpp
@@ -21,6 +21,25 @@ namespace TestCommon
         }
     }
 
+    winrt::event_token TestConfigurationSetProcessorFactory::Diagnostics(const EventHandler<DiagnosticInformation>& handler)
+    {
+        return m_diagnostics.add(handler);
+    }
+
+    void TestConfigurationSetProcessorFactory::Diagnostics(const winrt::event_token& token) noexcept
+    {
+        m_diagnostics.remove(token);
+    }
+
+    DiagnosticLevel TestConfigurationSetProcessorFactory::MinimumLevel()
+    {
+        return DiagnosticLevel::Informational;
+    }
+
+    void TestConfigurationSetProcessorFactory::MinimumLevel(DiagnosticLevel)
+    {
+    }
+
     IConfigurationUnitProcessorDetails TestConfigurationSetProcessor::GetUnitProcessorDetails(const ConfigurationUnit& unit, ConfigurationUnitDetailLevel detailLevel)
     {
         if (GetUnitProcessorDetailsFunc)

diff --git a/src/AppInstallerCLITests/TestConfiguration.h b/src/AppInstallerCLITests/TestConfiguration.h
@@ -13,7 +13,16 @@ namespace TestCommon
     {
         winrt::Microsoft::Management::Configuration::IConfigurationSetProcessor CreateSetProcessor(const winrt::Microsoft::Management::Configuration::ConfigurationSet& configurationSet);
 
+        winrt::event_token Diagnostics(const winrt::Windows::Foundation::EventHandler<winrt::Microsoft::Management::Configuration::DiagnosticInformation>& handler);
+        void Diagnostics(const winrt::event_token& token) noexcept;
+
+        winrt::Microsoft::Management::Configuration::DiagnosticLevel MinimumLevel();
+        void MinimumLevel(winrt::Microsoft::Management::Configuration::DiagnosticLevel value);
+
         std::function<winrt::Microsoft::Management::Configuration::IConfigurationSetProcessor(const winrt::Microsoft::Management::Configuration::ConfigurationSet&)> CreateSetProcessorFunc;
+
+    private:
+        winrt::event<winrt::Windows::Foundation::EventHandler<winrt::Microsoft::Management::Configuration::DiagnosticInformation>> m_diagnostics;
     };
 
     struct TestConfigurationSetProcessor : winrt::implements<TestConfigurationSetProcessor, winrt::Microsoft::Management::Configuration::IConfigurationSetProcessor>

diff --git a/src/AppInstallerSharedLib/AppInstallerLogging.cpp b/src/AppInstallerSharedLib/AppInstallerLogging.cpp
@@ -102,6 +102,11 @@ namespace AppInstaller::Logging
         m_enabledLevel = level;
     }
 
+    Level DiagnosticLogger::GetLevel() const
+    {
+        return m_enabledLevel;
+    }
+
     bool DiagnosticLogger::IsEnabled(Channel channel, Level level) const
     {
         return (!m_loggers.empty() &&

diff --git a/src/AppInstallerSharedLib/Public/AppInstallerLogging.h b/src/AppInstallerSharedLib/Public/AppInstallerLogging.h
@@ -135,6 +135,9 @@ namespace AppInstaller::Logging
         // For example; SetLevel(Verbose) will enable all logs.
         void SetLevel(Level level);
 
+        // Gets the enabled level.
+        Level GetLevel() const;
+
         // Checks whether a given channel and level are enabled.
         bool IsEnabled(Channel channel, Level level) const;
 

diff --git a/...crosoft.Management.Configuration.Processor/Exceptions/FindDscResourceNotFoundException.cs b/...crosoft.Management.Configuration.Processor/Exceptions/FindDscResourceNotFoundException.cs
@@ -7,6 +7,7 @@
 namespace Microsoft.Management.Configuration.Processor.Exceptions
 {
     using System;
+    using Microsoft.PowerShell.Commands;
 
     /// <summary>
     /// Resource not found by Find-DscResource.
@@ -16,16 +17,24 @@ internal class FindDscResourceNotFoundException : Exception
         /// <summary>
         /// Initializes a new instance of the <see cref="FindDscResourceNotFoundException"/> class.
         /// </summary>
-        /// <param name="unitName">Unit name.</param>
-        public FindDscResourceNotFoundException(string unitName)
+        /// <param name="resourceName">Resource name.</param>
+        /// <param name="module">Optional module.</param>
+        public FindDscResourceNotFoundException(string resourceName, ModuleSpecification? module)
+            : base($"Could not find resource: {resourceName} [{module?.ToString() ?? "<no module>"}]")
         {
             this.HResult = ErrorCodes.WinGetConfigUnitNotFoundRepository;
-            this.UnitName = unitName;
+            this.ResourceName = resourceName;
+            this.Module = module;
         }
 
         /// <summary>
-        /// Gets the unit name.
+        /// Gets the resource name.
         /// </summary>
-        public string UnitName { get; }
+        public string ResourceName { get; }
+
+        /// <summary>
+        /// Gets the module, if any.
+        /// </summary>
+        public ModuleSpecification? Module { get; }
     }
 }
diff --git a/src/Microsoft.Management.Configuration.Processor/Exceptions/GetDscResourceMultipleMatches.cs b/src/Microsoft.Management.Configuration.Processor/Exceptions/GetDscResourceMultipleMatches.cs
@@ -20,6 +20,7 @@ internal class GetDscResourceMultipleMatches : Exception
         /// <param name="resourceName">Resource name.</param>
         /// <param name="module">Optional module.</param>
         public GetDscResourceMultipleMatches(string resourceName, ModuleSpecification? module)
+            : base($"Multiple matches found for resource: {resourceName} [{module?.ToString() ?? "<no module>"}]")
         {
             this.HResult = ErrorCodes.WinGetConfigUnitMultipleMatches;
             this.ResourceName = resourceName;

diff --git a/src/Microsoft.Management.Configuration.Processor/Exceptions/InstallDscResourceException.cs b/src/Microsoft.Management.Configuration.Processor/Exceptions/InstallDscResourceException.cs
@@ -20,6 +20,7 @@ internal class InstallDscResourceException : Exception
         /// <param name="resourceName">Resource name.</param>
         /// <param name="module">Module.</param>
         public InstallDscResourceException(string resourceName, ModuleSpecification? module)
+            : base($"Unable to find resource after install: {resourceName} [{module?.ToString() ?? "<no module>"}]")
         {
             this.HResult = ErrorCodes.WinGetConfigUnitNotFound;
             this.ResourceName = resourceName;

diff --git a/src/Microsoft.Management.Configuration.Processor/Exceptions/InvokeDscResourceGetException.cs b/src/Microsoft.Management.Configuration.Processor/Exceptions/InvokeDscResourceGetException.cs
@@ -20,6 +20,7 @@ internal class InvokeDscResourceGetException : Exception
         /// <param name="resourceName">Resource name.</param>
         /// <param name="module">Optional module.</param>
         public InvokeDscResourceGetException(string resourceName, ModuleSpecification? module)
+            : base($"Failed when calling `Get` for resource: {resourceName} [{module?.ToString() ?? "<no module>"}]")
         {
             this.HResult = ErrorCodes.WinGetConfigUnitInvokeGet;
             this.ResourceName = resourceName;

diff --git a/src/Microsoft.Management.Configuration.Processor/Exceptions/InvokeDscResourceSetException.cs b/src/Microsoft.Management.Configuration.Processor/Exceptions/InvokeDscResourceSetException.cs
@@ -20,6 +20,7 @@ internal class InvokeDscResourceSetException : Exception
         /// <param name="resourceName">Resource name.</param>
         /// <param name="module">Optional module.</param>
         public InvokeDscResourceSetException(string resourceName, ModuleSpecification? module)
+            : base($"Failed when calling `Set` for resource: {resourceName} [{module?.ToString() ?? "<no module>"}]")
         {
             this.HResult = ErrorCodes.WinGetConfigUnitInvokeSet;
             this.ResourceName = resourceName;

diff --git a/...Microsoft.Management.Configuration.Processor/Exceptions/InvokeDscResourceTestException.cs b/...Microsoft.Management.Configuration.Processor/Exceptions/InvokeDscResourceTestException.cs
@@ -20,6 +20,7 @@ internal class InvokeDscResourceTestException : Exception
         /// <param name="resourceName">Resource name.</param>
         /// <param name="module">Optional module.</param>
         public InvokeDscResourceTestException(string resourceName, ModuleSpecification? module)
+            : base($"Failed when calling `Test` for resource: {resourceName} [{module?.ToString() ?? "<no module>"}]")
         {
             this.HResult = ErrorCodes.WinGetConfigUnitInvokeTest;
             this.ResourceName = resourceName;

diff --git a/src/Microsoft.Management.Configuration.Processor/Helpers/ConfigurationUnitAndResource.cs b/src/Microsoft.Management.Configuration.Processor/Helpers/ConfigurationUnitAndResource.cs
@@ -18,7 +18,6 @@ namespace Microsoft.Management.Configuration.Processor.Helpers
     /// </summary>
     internal class ConfigurationUnitAndResource
     {
-        private readonly ConfigurationUnitInternal configurationUnitInternal;
         private readonly DscResourceInfoInternal dscResourceInfoInternal;
 
         /// <summary>
@@ -35,24 +34,29 @@ public ConfigurationUnitAndResource(
                 throw new ArgumentException();
             }
 
-            this.configurationUnitInternal = configurationUnitInternal;
+            this.UnitInternal = configurationUnitInternal;
             this.dscResourceInfoInternal = dscResourceInfoInternal;
         }
 
+        /// <summary>
+        /// Gets or initializes the internal unit.
+        /// </summary>
+        public ConfigurationUnitInternal UnitInternal { get; private init; }
+
         /// <summary>
         /// Gets the configuration unit.
         /// </summary>
         public ConfigurationUnit Unit
         {
-            get { return this.configurationUnitInternal.Unit; }
+            get { return this.UnitInternal.Unit; }
         }
 
         /// <summary>
         /// Gets the directives overlay.
         /// </summary>
         public IReadOnlyDictionary<string, object>? DirectivesOverlay
         {
-            get { return this.configurationUnitInternal.DirectivesOverlay; }
+            get { return this.UnitInternal.DirectivesOverlay; }
         }
 
         /// <summary>
@@ -69,7 +73,7 @@ public string ResourceName
         /// </summary>
         public ModuleSpecification? Module
         {
-            get { return this.configurationUnitInternal.Module; }
+            get { return this.UnitInternal.Module; }
         }
 
         /// <summary>
@@ -79,7 +83,7 @@ public ModuleSpecification? Module
         /// <returns>The value of the directive. Null if doesn't exist.</returns>
         public string? GetDirective(string directiveName)
         {
-            return this.configurationUnitInternal.GetDirective(directiveName);
+            return this.UnitInternal.GetDirective(directiveName);
         }
 
         /// <summary>

diff --git a/src/Microsoft.Management.Configuration.Processor/Helpers/ConfigurationUnitInternal.cs b/src/Microsoft.Management.Configuration.Processor/Helpers/ConfigurationUnitInternal.cs
@@ -62,6 +62,15 @@ public ConfigurationUnitInternal(
         /// </summary>
         public ModuleSpecification? Module { get; }
 
+        /// <summary>
+        /// Creates a string that identifies this unit for diagnostics.
+        /// </summary>
+        /// <returns>The string that identifies this unit for diagnostics.</returns>
+        public string ToIdentifyingString()
+        {
+            return $"{this.Unit.UnitName} [{this.Module?.ToString() ?? "<no module>"}]";
+        }
+
         /// <summary>
         /// Get a directive from the unit taking into account the directives overlay.
         /// </summary>

diff --git a/src/Microsoft.Management.Configuration.Processor/ProcessorEnvironments/HostedEnvironment.cs b/src/Microsoft.Management.Configuration.Processor/ProcessorEnvironments/HostedEnvironment.cs
@@ -59,7 +59,7 @@ public void ValidateRunspace()
             // Only support PowerShell Core.
             if (this.GetVariable<string>(Variables.PSEdition) != Core)
             {
-                throw new NotSupportedException();
+                throw new NotSupportedException("Only PowerShell Core is supported.");
             }
 
             var powerShellGet = PowerShellHelpers.CreateModuleSpecification(