Powershell: Clean up stream messaging in Import-Module (specifically in ModuleCmdletBase)

[KirkMunro]

Summary of the new feature/enhancement

Import-Module is an example of how _not_ to use streams in PowerShell. If the Verbose stream is not silenced with S.M.A.ActionPreference.SilentlyContinue or S.M.A.AP.Ignore, Import-Module outputs a ton of useless information to the Verbose stream. This does nothing more than create noise, and causes problems for anyone wanting to turn on verbose stream output to get to the bottom of real problems.

As a scripter, I want to see Progress messages for any stream output that is intended to show progress of a command, so that I don't have progress messages cluttering up my log files.

As a scripter, I only want to see Verbose messages if they will help me troubleshoot a command that I invoked, so that I can get to the bottom of issues quickly without reading reams of irrelevant log messages.

As a command author, I only want to see Debug messages if they will help me diagnose why a command may be failing without using the debugger, so that I can get to the bottom of issues quickly without reading reams of irrelevant log messages.

Those three problem statements may not all apply here, but I wanted to call them out because the streams need to be used with intent, not just chosen arbitrarily to communicate some text message.

Proposed technical implementation details (optional)

Evaluate each of the Cmdlet.Write* invocations in https://github.com/PowerShell/PowerShell/blob/8f37cced709168f313a00b2e3ee7088495bbcd7a/src/System.Management.Automation/engine/Modules/ModuleCmdletBase.cs, and determine which stream should be used for each of the messages based on their intent, removing any messages that add no value whatsoever.

[mklement0]

I agree that the ModuleCmdletBase _base_ class isn't the appropriate place to place verbose/debug/progress messages for _all_ written-in-PowerShell modules (if I understand correctly).

In light of that, I suggest referencing ModuleCmdletBase in the issue's title, not Import-Module, because for the latter _specifically and exclusively_, the current, detailed export/import-related verbose messages _are_ helpful.

[iSazonov]

 ipmo posh-git -Verbose
VERBOSE: Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\posh-git\0.7.3\posh-git.psd1'.
VERBOSE: Importing function 'Add-PoshGitToProfile'.
VERBOSE: Importing function 'Add-SshKey'.
VERBOSE: Importing function 'Enable-GitColors'.
VERBOSE: Importing function 'Expand-GitCommand'.
VERBOSE: Importing function 'Get-AliasPattern'.
VERBOSE: Importing function 'Get-GitBranch'.
VERBOSE: Importing function 'Get-GitDirectory'.
VERBOSE: Importing function 'Get-GitStatus'.
VERBOSE: Importing function 'Get-PromptPath'.
VERBOSE: Importing function 'Get-SshAgent'.
VERBOSE: Importing function 'Get-SshPath'.
VERBOSE: Importing function 'Invoke-NullCoalescing'.
VERBOSE: Importing function 'Start-SshAgent'.
VERBOSE: Importing function 'Stop-SshAgent'.
VERBOSE: Importing function 'TabExpansion'.
VERBOSE: Importing function 'tgit'.
VERBOSE: Importing function 'Update-AllBranches'.
VERBOSE: Importing function 'Write-GitStatus'.
VERBOSE: Importing function 'Write-Prompt'.
VERBOSE: Importing variable 'GitPromptScriptBlock'.
VERBOSE: Importing alias '??'.

Do you want to remove all "VERBOSE: Importing function/cmdlet/alias" lines?

[KirkMunro]

In light of that, I suggest referencing ModuleCmdletBase in the issue's title, not Import-Module, because for the latter _specifically and exclusively_, the current, detailed export/import-related verbose messages _are_ helpful.

@mklement0: How are they helpful? If you invoke a command that results in implicit import of a module that contains 2000 cmdlets, how do those 2000 verbose messages help you? Or is there some other part of the verbose output that simply echoes line-by-line what is in a manifest or what you can find at any time using Get-Command -Module $moduleName that you find helpful?

Do you want to remove all "VERBOSE: Importing function/cmdlet/alias" lines?

@vexx32: I think that should be considered, yes. Or at a minimum, consolidation of the verbose information. Learning what commands are included in a module is basic, introductory PowerShell knowledge: you can check anytime using Get-Command -Module PoshGit. Spewing out dozens (or hundreds and more) verbose messages from a single command invocation should be questioned no matter what that command is, for the sole reason that commands are used in scripts, and having one command flood any message stream makes it difficult to very simply turn on verbose output to review additional details from an entire script. The signal to noise ratio becomes skewed way too dramatically in favor of noise.

Speaking as a PowerShell toolbuilder, there are many scenarios where I want to simply have verbose logging turned on by default, because I'm running scripts unattended and should something happen, I want the extra detail immediately, without having to go back and try to reproduce whatever happened and get the detail at that point in time. If those scripts that run unattended produce logs that are flooded with noise, it becomes much more difficult to get to the bottom of what is going on should a problem occur.

PowerShell logs should be intentional, enough information to be useful, but not so much information that it becomes spam. Perhaps a single message indicating what was imported. Something like "VERBOSE: Imported 19 functions and 1 alias from module PoshGit.". Note I didn't include the variable count there, because having verbose messages for variables that are imported _is_ useful since there is no discovery mechanism for those, but for cmdlets, functions and aliases, there are better ways to get that information that allow message logs to be consumed more easily. Personally though, I would just pull those messages entirely, because they don't help in understanding what is technically going on should an issue occur.

I also think PowerShell streams are misunderstood, and therefore misused. My take:

• Verbose is for messages that will help users troubleshoot why a command that they invoked interactively or in their script may have failed, when the error message itself is not enough. It is also to report information that is not otherwise available (site redirects on a REST API invocation, etc.), which again is intended to help someone understand a bit more technical detail to troubleshoot issues.

• Debug is for messages that will help a command author understand why their command is failing when someone else invoked it (or when they invoked it if they are actively debugging it). These can contain more internal details, and there may be many debug messages if they are necessary for deep troubleshooting, but their target audience is command authors

• Progress is for messages that communicate progress in longer running commands or scripts.

• Information is for messages that help a user understand what is being done in a script (if they are reviewing an ongoing run log or console where a command is running) or what was done by a script (if they are reviewing output of a script after the fact). It is also for developers to have additional streams if they need to pass information through PowerShell, where they can tag the stream and then have specific handling for that stream, passing object data out to a runtime.

My focus is not interactive use (which is what the current verbose messages output from Import-Module seem to be targeting). My focus is large scale unattended enterprise automation, and being able to consume useful logs during execution or after the fact. I've already worked around the verbose logging issue I'm calling out here, but to do so I had to turn off verbose logging from all invoked commands, and leave verbose logging on only for explicit Write-Verbose calls in scripts that are run unattended. I would have preferred simply capturing all verbose messages in the logs, but neither myself nor my customers want to sift through noise when reviewing log files.

[mklement0]

@KirkMunro

How are they helpful?

I meant that if you call Import-Module _directly_, such as in the context of developing a module, these messages are helpful, as they tell you whether what you meant to export is actually being exported: it helps both with discovering _automatic_ exports and verifying that your manifest / *.psm1 file work correctly.

I fully agree that _implicit_ use of Import-Module should _not_ result in these messages (or perhaps perhaps a _single_ message at most, as you propose) - but I have not looked into any implementation / refactoring issues / conceptual hurdles involved, except to note that putting such messages into a _base_ class that many cmdlets besides Import-Module are based on sounds like the wrong place.

[SeeminglyScience]

@KirkMunro I get the feeling your issue isn't really with the verbose messages that Import-Module emits but with how verbose preference is propagated. I feel the same way and tbh it's part of why I mostly don't bother with writing to alternate streams in script command. If I want write verbose messages, then the user also has to deal with all of the verbose messages of every command I use internally.

It might be too late to change any of that, but it's not really a good reason remove verbose messages from commands that already use it. For instance, I've 100% used Import-Module's verbose messages to troubleshoot module loading. It's actually one of a small handful of commands where that's turned out to be useful.

[KirkMunro]

@SeeminglyScience: There's no doubt that the verbose messages may be useful to troubleshoot module loading; however, there is also no doubt that the volume of messages produced by module loading pollutes the logs produced by a script when verbose logging is enabled.

1. Are they the _right_ messages to troubleshoot the issues that you encountered?
2. Is Verbose the right level of detail for those messages? Or would Debug be a better fit for users who are debugging modules, now that -Debug doesn't prompt users anymore?
3. Is the quantity of messages generated appropriate for the command? The signal to noise ratio is way off at the moment.
4. If you are debugging module loading, is it about your own modules, where you want to make sure that the proper resources are exported from the module? Aren't there better tools for that already in PowerShell? The lack of an error message should be indicative of success without having verbose messages to add flavor, and when it comes to exports, as suggested, the messages produced could be compressed dramatically.

Also, do you feel that module/command authors should be the target for -Verbose messages?

Lots of questions, I know. But just because ipmo -Verbose _can_ be useful, doesn't mean it's the right solution for what it is trying to accomplish.

[KirkMunro]

Also @SeeminglyScience: you are correct, my issue extends beyond Import-Module (PowerShellGet cmdlets are also a bit too verbose-happy), but I can't think of one other command where I think verbose usage went so far like this, and it's such a core piece of functionality that I think it's worth figuring out if there isn't a better way.

[vexx32]

Tbh much of the current verbose output _feels_ like it'd be better placed with -Debug instead, especially all the "exporting"/"importing" messages.

I agree that they're sometimes useful, but those use cases are few and far between from what I've seen myself, and it's much more useful when an author is debugging the import than when a user / automation task wants some slightly more detailed logging information.

[SeeminglyScience]

there is also no doubt that the volume of messages produced by module loading pollutes the logs produced by a script when verbose logging is enabled.

So first things first, I don't think auto loading should emit any verbose output. I'm with you there, that doesn't make sense imo. Aside from auto loading again I think the issue is with propagation not the command itself. I think that when the Verbose switch is specified that it shouldn't propagate past the callee. Way too often it ends up being a flood of implementation detail noise.

Can that be changed? 🤷

1. Are they the _right_ messages to troubleshoot the issues that you encountered?

Yeah I think so. It's detailing what's happening in a way that isn't super implementation detail specific.

1. Is Verbose the right level of detail for those messages? Or would Debug be a better fit for users who are debugging modules, now that -Debug doesn't prompt users anymore?

It's mostly just detailing what it's doing. I imagine debug to be more for state dumps or other very implementation detail specific information.

1. Is the quantity of messages generated appropriate for the command? The signal to noise ratio is way off at the moment.

If you're trying to get verbose information about Import-Module I think it's appropriate.

Also, do you feel that module/command authors should be the target for -Verbose messages?

Actually I've only ever used it as a consumer. As an author I just debug the psm1.

1. If you are debugging module loading, is it about your own modules, where you want to make sure that the proper resources are exported from the module?

The occasions that I've used it it's been tracking down an issue with someone else's module that I've installed.

[mklement0]

I've hidden my previous comments on realizing that I had jumped to conclusions and misremembered things. Take two:

• Only the *-Module cmdlets derive from ModuleCmdletBase.

• From what I can tell, auto-loading does _not_ trigger Import-Module's verbose messages, only explicit Import-Module calls:

# Auto-loading: Verbose Import-Module messages are NOT emitted.
& { [CmdletBinding()] param() Remove-Module PSReadLine; (Get-PSReadLineOption).EditMode; Write-Verbose Done. } -vb

# Explicit loading: Verbose Import-Module messages ARE emitted.
& { [CmdletBinding()] param() Import-Module PSReadLine; (Get-PSReadLineOption).EditMode; Write-Verbose Done. } -vb

• I agree with @SeeminglyScience that the primary problem is that turning on verbose output for _advanced scripts / functions_ (as opposed to cmdlets) results in unwanted noise, because verbose output is then turned on _for all commands called inside that script / function too_ rather than just for the Write-Verbose statement directly contained in the script / function; calls to _other_ commands inside a script/function should be considered an _implementation_ detail and therefore _not_ produce verbose output (unless explicitly requested).

  • This is a consequence of PowerShell's dynamic scoping, which even applies in the case of passing the -Verbose _switch_, which PowerShell translates to a function/script-local $VerbosePreference _variable_ with value Continue, which all descendant scopes therefore see.

The following workaround is too cumbersome in practice, but it shows what I think the behavior should be:

& {
  [CmdletBinding()]
  param()

  # If verbose output is turned on, hide the setting from the descendant scopes,
  # but make all Write-Verbose calls *in this scope only* emit verbose output.
  if ($VerbosePreference -eq 'Continue') {
    $VerbosePreference = 'SilentlyContinue' # Hide from cmdlet calls and descendant scopes.
    # Apply only to Write-Verbose calls in the current scope.
    $private:PSDefaultParameterValues = $PSDefaultParameterValues ? $PSDefaultParameterValues.Clone() : [System.Management.Automation.DefaultParameterDictionary]::new()
    $private:PSDefaultParameterValues['Write-Verbose:Verbose'] = $true
  }

  # This is now quiet.
  Import-Module PSReadLine

  # Simulate a call to other PowerShell functions / scripts:
  # This is now quiet too.
  & {
    Write-Verbose 'in child scope'
  }

  # Only this will print.
  Write-Verbose Done.

} -Verbose

[vexx32]

From memory, if $VerbosePreference is set to a visible state before running something that causes an auto-import, it _will_ dump a ton of things to the verbose stream.

Also, I might be misremembering, but I _think_ it'll do similar if running a script from a file on disk with -Verbose (which will need it to have cmdletbinding, of course).

[mklement0]

@vexx32, my previous examples show that neither is the case, and from the global scope you can verify with
Remove-Module PSReadLine; $VerbosePreference = 'Continue'; (Get-PSReadLineOption).EditMode

[mklement0]

Is there something unclear about my previous example, @vexx32? It ensures that module PSReadLine isn't loaded, turns on verbose output globally, and triggers auto-import of PSReadLine via the Get-PSReadLineOption call - and _no_ verbose messages print. Doesn't that contradict your claim, or am I missing something?

[SeeminglyScience]

@mklement0 looks like it does on first import, but not if the module was already loaded at one point. For binary modules at least.

[vexx32]

No, it definitely does spam verbose stream. I wonder if it's different for PSReadLine for some reason (are compiled modules different?)... but, as a quick example, try executing any PowerShellGet (2.x, haven't tried with the betas of v3) command before having it imported and with $VerbosePreference set.

Remove-Module PowerShellGet, PackageManagement
$VerbosePreference = 'Continue'
Find-Module PSWordCloud

I can reproduce on consecutive re-imports with script modules, so I can only assume that oddity is specific to binary modules.

[SeeminglyScience]

Okay so auto loading itself doesn't trigger it, it's the same preference propagation problem. The module I was testing with had logic in the psm1 to Import-Module a dll.

So technically it's not triggering during auto load, but if you auto load a script module it looks like it anyway.

[mklement0]

@SeeminglyScience, there is another factor at play, because with _self-contained_ modules I see it neither with binary nor with script modules:

# Binary module:
# In a pristine session, before ever having imported the 'ThreadJob' module (via a Start-ThreadJob) call:
$VerbosePreference = 'Continue'; $null = Start-ThreadJob { 'hi' }; $VerbosePreference = 'SilentlyContinue'

# Script module:
# Uses the 'Native' module (Install-Module Native)
$VerbosePreference = 'Continue'; ins echo; $VerbosePreference = 'SilentlyContinue'

The culprit is loading _dependent_ modules via a _module manifest_'s RequiredModules key: modules automatically imported this way indeed generate verbose output (but only for these dependent modules) - which is arguably a _bug_.

It also explains @vexx32's symptom, because PowerShellGet loads PackageManagement via the RequiredModules entry.

Update: Additionally, the problem surfaces with _nested modules_ loaded via the NestedModules key and run-on-import-in-the-caller's-scope scripts specified via the ScriptsToProcess key, as well as with any code that runs in the _script_ scope of *.psm1 files being imported, notably Export-ModuleMember - in short: any _cmdlet calls_ and any _PowerShell code_ that is automatically run during import can surface verbose output.

[vexx32]

That's part of it, I think, but I think it also has to do with whether the script module uses Export-ModuleMember. For example, PSKoans doesn't use that (though it has its own verbose messaging which I'm now considering just removing lol) and it doesn't get the same behaviour; all its exports are only defined by the PSD1.

Pester, on the other hand, _does_.

Though it does look like loading via RequiredModules adds some additional bits and pieces.

[mklement0]

@vexx32, for Export-ModuleMember calls this is to be expected: they execute in PowerShell code that acts on $VerbosePreference set to Continue (either via an ancestral variable or via -Verbose); note that the messages are _Export-ModuleMember's_, not Import-Module's.

As such, this is simply another manifestation of the dynamic scoping problem discussed above, and something the workaround would eliminate.

[mklement0]

Let me try to summarize:

There are two _independent_ problems:

• How the existing (in-box) cmdlets may use the various output streams inappropriately or too liberally:

  • (a) Reviewing the in-box cmdlets seems worthwhile, but one thing we need to be clear on: are the streams other than 1 and 2 (success and error) considered part of a cmdlet's public contract? In other words: have we made it clear and can we reasonably assume that existing code out there _doesn't_ rely on existing verbose / debug / information messages not to change?

  • (b) To guide all command authors with respect to stream use in the future, I've asked for a new conceptual help topic, about_Streams, and I've copied some of @KirkMunro's thoughts there - see https://github.com/MicrosoftDocs/PowerShell-Docs/issues/6643

• How as a user you get _additional verbose output that you didn't ask for_, resulting in unwanted noise that drowns out the information of interest:

  • (c) We've seen that _auto-loading_ of modules is quiet for the modules _themselves_, but _not for their dependencies_, if any, and _not_ for script-level *.psm1 code, notably Export-ModuleMember calls, if any (I've updated the comment above to hopefully list all specific scenarios).

    • I suspect the current, inconsistent behavior is a fallout from the implementation rather than by design: seemingly, any cmdlet call and PowerShell code that executes during auto-import can surface verbose messages.
    • My vote is to resolve this inconsistency so that auto-import is _always_ quiet.
    • See #13657

  • [Withdrawn after further discussion in #13658] (d) The bigger problem is the dynamic scoping issue detailed above, causing calls to _other commands_ inside scripts / functions to emit verbose output too.

    • Again, the question is whether fixing this would be considered a breaking change; even if not, we need to think through how to fix it.

[mklement0]

I've created #13657 for (c) and #13658 for (d).

[KirkMunro]

Regarding the first problem, I think I've come up with a solution that should work for everyone. For this to work though, the docs need to explicitly call out the proper guidance (the new docs do not provide sufficient guidance yet), and we of course need to agree that this is the proper approach.

A lot of the issues I have with PowerShell these days, this issue being no exception, stem from the needs of the interactive user being entirely different from the needs of the automator. Teams building PowerShell functionality do very well for the former, because it is easier -- they can test it very easily in the PowerShell console; however, they generally don't do as well for the latter.

In this case, as well as in all cmdlets, the developer needs to decide if the message they are outputting is for interactive use or not. If it is for interactive use (examples include welcome messages like you get from Connect-MgGraph, messages about cmdlets using non-approved verbs like you get from Import-Module, and messages about what was imported into a session like you get from Import-Module), the best vehicle that we have today to communicate such messages is writing them to the information stream with an Interactive tag. Tagging messages is the key. Any message that only has usefulness in an interactive session should be written this way. The benefit of this approach is that such messages could be completely silenced whenever PowerShell is run in a non-interactive session.

It may be useful to support tagging for messages written to other streams such as the Verbose stream, but I think getting messages meant for display in an interactive session are by their very nature informational messages, so the Information stream with an appropriate tag seems very appropriate for these types of messages. That would allow both interactive scenarios to be supported as they are today, while allowing back-end, unattended automation scenarios to run silently unless there is something important enough to write to one of the streams.

If this is an agreed upon approach, we may need some new functionality, such as an easy mechanism to silence interactive informational messages so that they don't clutter up Azure Function logs or other unattended automation logs with noise that is irrelevant to the person reviewing those logs, unless we can determine that the session is interactive and automatically silence those messages in the runtime in those scenarios.

Thoughts?