Write-Host Debugging

Was dem VBScript-Programmierer sein "WScript.Echo" ist, ist für PowerShell das "Write-Host". Einfach mal schnell an verschiedenen Stellen des Skripts eine Bildschirmausgabe auswerfen um damit den Fortschritt des Skripts zu erkennen oder andere Informationen auszugeben. Zudem gibt es noch "Write-Warning" und "Write-Error", um Fehler und Warnungen farblich in guter PowerShell-Manier auszugeben. Wer Skripte unbewacht laufen lässt, wird sich freuen, dass diese Ausgaben mit "Start-Transcript" auch noch in eine Datei ausgegeben werden können. Aber es funktioniert nicht immer und wie wäre ein "besseres Write-Host", welches verschiedene Levels unterscheidet, Meldungen woanders hin sendet etc.

Microsoft nutzt z.B.: im Skript  CVE-2023-23397.ps1 (Quelle: https://microsoft.github.io/CSS-Exchange/Security/CVE-2023-23397/) auch den Trick die Funktion "Write-Host" umzuschreiben.

Write-Host, Pipeline und Transcript

Wer heute ein Skript schreibt, sucht natürlich nach einer Möglichkeit zur Ausgabe von Meldungen. Da in PowerShell aber auch vieles über die Pipeline übertragen wird, muss man nun abwägen, ob ich die Ausgaben einfach so auf STDOUT sende. Solche Ausgaben kann ein per Pipeline angeschlossene Skript dann natürlich weiter verarbeiten. Oft ist aber genau das störend und man möchte nur die Ergebnisse in die Pipeline ausgeben. Diagnoseausgaben sollen auch auf der Konsole sichtbar sein aber eben nicht in der Pipeline landen.

Achtung: Seit PowerShell 5 ist "Write-Host" nur ein Alias für Write-Information.

The Write-Host cmdlet customizes output. You can specify the color of text by using the ForegroundColor parameter, and you can specify the background color by using the BackgroundColor parameter. The Separator parameter lets you specify a string to use to separate displayed objects. The particular result depends on the program that is hosting PowerShell. Note Starting in Windows PowerShell 5.0, Write-Host is a wrapper for Write-Information This allows you to use Write-Host to emit output to the information stream. This enables the capture or suppression of data written using Write-Host while preserving backwards compatibility. The $InformationPreference preference variable and InformationAction common parameter do not affect Write-Host messages.
Quelle: Write-Host https://docs.microsoft.com/en-us/powershell/module/microsoft.powershell.utility/write-host?view=powershell-6

Um das zu testen, habe ich eine kleine PS1-Datei angelegt, die verschiedene Ausgaben generiert.

[CmdletBinding()]
param()

start-transcript -path c:\temp\transcript.txt
$DebugPreference="Continue" 
write-host "Write-Host" 
write-verbose "Write-verbose" 
write-debug "Write-debug" 
write-error "Write-error" 
write-host "Write-host" 
out-host -inputobject "out-host"
stop-transcript

Die Ausgabe in der Datei ist zumindest bei mir sehr umfangreich, wenn die die Befehle interaktiv ausführe:

Im Transcript ist hier quasi alles drin, was auch auf der Konsole erschienen ist. Nur die "Verbose-Ausgabe fehlt, da ich diesen nicht als Parameter angegeben hatte. Die gleichen Befehle habe ich dann als PS1-Datei abgelegt und ausgeführt. Da hier die Befehle selbst nicht auf der "Konsole" erscheinen, kommen nur die Ausgaben zum Vorschein.

Hier ist nun auch die Verbose-Ausgabe vorhanden und im Transcript fehlen die eigentlichen Befehle, die auch nicht auf der Konsole erscheinen.

Write-Host fehlt im Transcript

Auch wenn so erst einmal alles "ordentlich" aussieht, so gibt es dennoch die ein oder anderen Probleme. Ich nutze ja die PowerShell auch für Skripte die automatisch ablaufen. Sie werden z.B. für den Taskplaner gestartet und hier ist mir für ein "Logging" natürlich wichtig, die Ausgaben auch temporär in einer Datei zu protokollieren. Schließlich ist kein Skript "fehlerfrei" und auch wenn ich den Fehler abfange und mit "Exit <Fehlernummer>" dem aufrufenden Task mitgebe, so komme ich dann erst einmal nicht mehr an die Bildschirmausgaben heran.

Daher habe ich bislang immer intensiv ein "Start-Transcript" mit einem Zeitstempel gestartet. Die Zeilen sehen dann wie folgt aus:

[string]$transcriptfile = (".\logs\console."+(get-date -format "yyyy-MM-dd-HH-mm-ss-fff")+".log")
write-host "Start Transcript to " $transcriptfile 
Start-Transcript -path $transcriptfile
# hier dann der weitere Code

Natürlich muss ich am Ende das Transcript wieder stoppen und mich auch um das Aufräumen der alten Logs z.B. über das Alter kümmern.

Komischerweise gibt es immer wieder Server, auf denen das Logfile quasi "leer" bleibt. Da steht dann nur folgendes drin:

**********************
Windows PowerShell Transcript Start
Start time: 20160520152344 Username  : MSXFAQ\SVC-JOB 
Machine	  : JOBSERVER01 (Microsoft Windows NT 6.1.7601 Service Pack 1) 
**********************
Transcript started, output file is C:\Tasks\tool1\logs\console.2016-05-20-15-23-44-291.log

**********************
Windows PowerShell Transcript End
End time: 20160520152505
**********************

Warum das so ist, habe ich bislang noch nicht ermitteln können. Es scheint an der Build-Version von PowerShell zu liegen, denn es gibt wohl Hinweise im Internet über dieses Problem und auch Links auf entsprechende Updates und Hotfixes. Einige Leute berichten, dass es das Windows Update 3000850 war.

„… In my testing I discovered that this bug only appears after installing KB3000850
I found the issue in KB3000850 since it's a later rollup that includes everything in KB2919355
https://www.microsoft.com/de-DE/download/details.aspx?id=44975  (700MB, Nov 14)
https://support.microsoft.com/en-us/kb/3000850
Aber das kam schon November 2014 raus und ich habe das Problem auch im Sommer 2016 wieder gehabt

Dann bin ich auf ein Hotfix vom April 2015 gestoßen.

Aber in den Microsoft Foren fand ich auch Aussagen wie:

Oder auch „This is how PowerShell is designed to work. Output is only visible in the console.“
Oder “A similar issue is happening on powersherll 5, Windows Server 2008 R2. When the write-host comes from a remote machine it dones't works:”

Write-Host does not pollute the output stream.
Quelle: Understanding Streams, Redirection, and Write-Host in PowerShell
https://blogs.technet.microsoft.com/heyscriptingguy/2014/03/30/understanding-streams-redirection-and-write-host-in-powershell/

Hilfreicher was dann aber ein BlogPost von Jeffrey Snover, der PowerShell-Designer, der mit dem Satz „Using Write-Host is almost always wrong.“ startet und das auch erklärt.

Hinweis
Jeffrey Snover rät davon ab, mit "Write-Host" Debug-Ausgaben zu schreiben, da sie "nur" auf der Konsole erscheinen und daher nicht weiter verarbeitet werden können. Das widerspricht dem Ziel Code wieder zu verwenden. Write-Host ist aber durchaus in Ordnung für z.B. die Gestaltung einfacher Oberflächen u.a.
Siehe auch http://www.jsnover.com/blog/2013/12/07/write-host-considered-harmful/

Im ersten Moment war ich auch irritiert, so wie ich mein „Write-host“ Liebgewonnen habe und natürlich möchte ich nun nicht alles mit „Write-Output“ raus jagen. Vor allem stören mich ja die „Bildschirmausgaben“ in der Pipeline für nachfolgende Programme, die das alles gar nicht brauchen.
Also dann doch mehr mit einem „Write-Verbose/Write-Debug/Write-Error“ arbeiten ? Jemand hat sogar schon eine „Ersatzfunktion“ gebaut.

Function Write-Host ($message,$nonewline,$backgroundcolor,$foregroundcolor) {
   $Message | Out-Host
}

So kann man seine Skript unangetastet lassen und die Ausgabe einfach auf ein "Out-Host" umleiten. Natürlich alles ohne die Farben etc.

Mittlerweile nutzt ich schon fast häufiger die Write-Output-Funktion denn so eine Umschreibe-Funktion, denn Write-Output nutzt die gleichen Parameter.

Write-Verbose

Nachdem nun allen klar ist, dass Write-Host" für Ausgaben auf den Bildschirm, und nur auf den Bildschirm, optimal ist, stellt sich natürlich die Frage wie ich eine Ausgabe so erstelle, dass ich sie sehen aber auch loggen kann. Dazu gibt es vier (und aber Powershell5 mit Write-Information noch eine fünfte) Optionen:

Write-Error
Write-Warning
Write-Verbose
Write-Debug

Der große Unterschied zu Write-Host ist hier, dass die Ausgaben jeweils in eine eigene Pipe gehen, die aber per Default auch auf dem Bildschirm landet. Sie kann aber umgeleitet werden. Die Meldung selbst muss als ein String übergeben werden oder als Wert des Parameters "-Message". Insofern reicht einfaches "Suchen und Ersetzen" von Write-Host durch Write-Verbose meist nicht aus.

Ob Write-Verbose oder eine der der anderen Ausgaben wirklich was auf die Konsole schreiben hängt von den Preferences ab:

Preference Default Bemerkung

$VerbosePreference

SilentlyContinue

Das Skript wird weiter abgearbeitet und es wird keine Ausgabe auf die Konsole ausgegeben. Um dies zu ändern, muss die Preference auf "Continue" gestellt werden

$WarningPreference

Continue

Die Warnung wird schon bei der Default-Einstellung ausgegeben

$ErrorActionPreference

Continue

Die Warnung wird schon bei der Default-Einstellung ausgegeben

$DebugPreference

SilentlyContinue

Das Skript wird weiter abgearbeitet und es wird keine Ausgabe auf die Konsole ausgegeben. Um dies zu ändern, muss die Preference auf "Continue" gestellt werden

Wer also nun statt "Write-Host" das Logging über Write-Verbose erzeugt, wird per Default wieder nichts sehen, es sei denn er ändert die Preference z.B. mit.

$VerbosePreference="Continue"

Wenn Sie den Konzepten von PowerShell folgende, dann sollten Sie dies aber so nicht machen, sondern die Verbose-Ausgabe ebenfalls als Parameter für ihr Skript hinterlegen. Der erste Ansatz ist dann der folgende:

param (
   [switch]$verbose
)

if ($verbose) {
   $VerbosePreference="Continue"
}

Noch besser ist es aber direkt über de CMDLetBinding zu gehen, welches aber immer einen Param-Block braucht:

[CMDLetBinding()]
param ()

write-verbose "test"

Dann aber können Sie einfach den Parameter "-Verbose" addieren um die Ausgabe zu aktivieren

Debug-Ausgaben und Start-Job

Ich hatte ja schon geschrieben, dass ich Write-Host auch gerne nutze, weil man damit mit "-nonewline" und den Farben auch die Ausgabe etwas gliedern kann. Aber ich muss Jeffrey Snover schon recht geben, dass solche Ausgaben ja auch sonst nur auf der Konsole erscheinen. Was passiert aber, wenn ein Modul eben gar keine Konsole hat, z.B.: wenn der Code als "Job" im Hintergrund läuft.

Hier durfte ich lernen, dass die Verbose und Debug-Ausgaben sehr wohl z.B. bei einem Job abgerufen werden können. Das funktioniert sogar während des Jobs. Der Aufruf des obigen Beispiels erfolgt mit:

start-job -FilePath .\psdebug.ps1

Die Ergebnisse des Jobs sind dann mit "Get-Job" abrufbar:

PS C:\> Get-Job | fl


HasMoreData   : True
StatusMessage :
Location      : localhost
Command       : [CmdletBinding()]
                param()

                start-transcript -path c:\temp\transcript.txt
                $DebugPreference="Continue"
                write-host "Write-Host"
                write-verbose "Write-verbose"
                write-debug "Write-debug"
                write-error "Write-error"
                write-host "Write-host"
                out-host -inputobject "out-host"
                stop-transcript
JobStateInfo  : Completed
Finished      : System.Threading.ManualResetEvent
InstanceId    : 88ab8ac3-5b54-42a3-88a8-1835c4f2b69d
Id            : 2
Name          : Job2
ChildJobs     : {Job3}
PSBeginTime   : 04.08.2016 19:36:46
PSEndTime     : 04.08.2016 19:36:58
PSJobTypeName : BackgroundJob
Output        : {}
Error         : {}
Progress      : {}
Verbose       : {}
Debug         : {}
Warning       : {}
State         : Completed

Allerdings startet mein Aufruf einen zweiten "Child-Job" und dessen Ausgabe sind interessant.

PS C:\temp> get-job 3 | fl


StatusMessage :
HasMoreData   : True
Location      : localhost
Runspace      : System.Management.Automation.RemoteRunspace
Command       : [CmdletBinding()]
                param()

                start-transcript -path c:\temp\transcript.txt
                $DebugPreference="Continue"
                write-host "Write-Host"
                write-verbose "Write-verbose"
                write-debug "Write-debug"
                write-error "Write-error"
                write-host "Write-host"
                out-host -inputobject "out-host"
                stop-transcript
JobStateInfo  : Completed
Finished      : System.Threading.ManualResetEvent
InstanceId    : 0d2846fa-a500-497f-a0a8-5199784a8e4a
Id            : 3
Name          : Job3
ChildJobs     : {}
PSBeginTime   : 04.08.2016 19:36:57
PSEndTime     : 04.08.2016 19:36:58
PSJobTypeName :
Output        : {}
Error         : {NotSupported,Microsoft.PowerShell.Commands.StartTranscriptComm
                and, Microsoft.PowerShell.Commands.WriteErrorException, NotSupp
                orted,Microsoft.PowerShell.Commands.StopTranscriptCommand}
Progress      : {}
Verbose       : {}
Debug         : {Write-debug}
Warning       : {}
State         : Completed

Hier ist dann auch bei "Debug" die Ausgabe zu sehen. Insofern gibt es schon einen Anreiz zukünftig Diagnoseausgaben statt mit Write-Host einfach mit "Write-Verbose" zu erstellen oder zumindest zusätzlich zu erstellen und Write-Host nur für die "schöne Ausgabe" auf den Bildschirm zu nutzen, die vielleicht nicht immer im Transcript erscheint.

Microsoft ADSync

Microsoft selbst hat die Notwendigkeit solcher Routinen auch verstanden aber leider nicht in PowerShell eingebaut. So findet sich dann auch z.B. im ADSync-Installationsverzeichnis "C:\Program Files\Microsoft Azure Active Directory Connect\Tools" die Datei "ADConnectivityTool.psm1", in der folgende Funktion definiert wurde:

#Auxiliary Function that writes an output to a log file or the PowerShell window
Function Write-Log {
    [CmdletBinding()]
    Param(
        [Parameter(Mandatory=$False, Position=1)]
        [string] $Message,

        [Parameter(Mandatory=$False, Position=2)]
        [string] $ForegroundColor = "Cyan"
    )
    Switch ($ForegroundColor)
    {
        Green { $Severity = "SUCCESS" }
        Red { $Severity = "ERROR  " }
        Default { $Severity = "INFO   " }
    }
    If($LogFileLocation)
    {
        If($Message -ne "")
        {
            $Message = "[" + (Get-Date).ToString() + "] [$Severity] " + $Message
            Out-File -Append -FilePath $LogFileLocation -InputObject $Message
        }
    }
    Else
    {
        Write-Host $Message -ForegroundColor $ForegroundColor
    }
}

Auch das ExchangeSetup-Skript hat eine Funktion und ich bin sicher, dass es noch ganz viele andere Varianten gibt. Logging und Protokollierung ist einfach ein notwendiger Baustein und es ist eigentlich schade, dass die PowerShell dort nichts mitbringt.

Der Ansatz ist nett aber funktioniert nur für Skripte, die dann auch konsequent auf Write-Host verzichten und die alternative Funktion nutzen.

Mein "Write-Log"

Mein Ansatz beruht darauf, dass ich einfach "Write-Host" umdefiniere

So einfach alle Skripte umzustellen finde ich natürlich nun nicht elegant. Ich würde schon gerne "Write-Host" weiter nutzen um Ausgaben elegant und formatiert auf die Konsole zu schreiben. Ich möchte aber auch, dass diese Daten im Transcript landen. Meist sind es ja Skripte, die klein anfangen und erst später größer und umfangreicher werden. Bislang stand ich dann vor dem Problem, in ein solches Skript ein vernünftiges Logging nachzurüsten. für VBScript hatte ich schon länger eine passender Klasse "Debugwriter" (Siehe VBSToolbox).

Ich habe dann erst mal eine kleine Testserie gemacht, indem ich eine Funktion "Write-Host" geschrieben habe, die ich z.B. vor dem Skripte einmal definiere:

Funktion Beschreibung

Ersetzen von Write-Host

function Write-host ($message) {
   "test1: $($message)"
}

Ich habe erst einmal geprüft, was meine Skripte machen, wenn ich "Write-Host" neu definiere. Der aufruf von Write-Host wurde dann auf mein Skript umgeleitet

 
function Write-host ($message) {
   write-host "Test2: $($message)"
}

Dann wolle ich natürlich wissen, was in der Funktion passiert. Wie erwartet kam es zu einer Rekursion und Endlosschleife. So geht es also nicht

 
function Write-host ($message) {
   Microsoft.PowerShell.Utility\write-host "dd $($message)"
}

Nun habe ich das Modul explizit angegeben und damit die Schleife durchbrochen.

Damit war der Weg vorgezeichnet. Ich musste mein eigene "Write-Host"-Funktion einfach so stricken, dass Sie meinen Anforderungen genügt und auch die ganzen Parameter mit nimmt, die ich dann aber auch ans native "Write-Host" wieder zur Ausgabe weitergeben kann. Einige "schlaue Erweiterungen würde ich mir da schon noch wünschen

Erweiterung Beschreibung

Weiterverarbeitung per Syslog o.a.

Meine Idee ist, nach einer weiteren Funktion zu suchen und wenn diese vorhanden ist, die Ausgabe auch dorthin zu senden. Quasi eine dynamische Erweiterung um Log4L, Syslog und andere Dinge einfach einzubinden.

Denkbar ist natürlich auch eine generell globale Variable zur Steuerung des Skripts

Severity

Ich unterscheide eigentlich immer Info, Warn, Error, Debug1-n. Natürlich kann ich das mit "Write-Error" ausgeben aber ich nutze im Write-Host auch gerne ein Prefix wie "Err:", "Wrn:", "Inf:", gefolgt von einem Fehler

Zeitstempel

Wie oft schreibe ich in meine "Write-Host"-Debug-Ausgaben einen Zeitstempel mit Get-Date. Das kann ich mir sparen, wenn das die neue Write-Host-Funktion macht.

Script-Name

Wenn mehrere PowerShell Script und Module sich gegenseitig aufrufen, dann könnte die Write-Host Funktion auch diese Information addieren.

Farbliche Ausgabe

Ich kann mit "-foregroundcolor" und "-backgroundcolor" manuell Farben vorgeben. Zumindest bei Fehlern o.ä. könnte das Write-Host auch alleine machen

Am Schluss kommt dann ein generische Ausgabeformat wie folgt raus:

2021-06-13 19:32:53Z, Scriptname, INF0, Dies ist eine Write-Host ausgabe
2021-06-13 19:32:53Z, Scriptname, WRN0, Dies ist eine Warnung, die Write-Host am 
2021-06-13 19:32:53Z, Scriptname, ERR0, Dies ist dann eine Fehlermeldung

Als CSV-Datei kann man das einfacher in eine Datei schreiben und filtern. Alternative kann eine Ausgabe ins Eventlog o.ä. erfolgen

Also habe ich mir mal ein "durchschnittliches Script" angeschaut und habe gemerkt, dass ich sehr viele Write-Host-Zeilen nutze und über eine Einrückung quasi den Level oder die Wichtigkeit definieren. Da sich die Parameter als auch das Skriptverhalten bei Write-Host von Write-Warning und Write-Error (Skript könnte abbrechen) unterscheidet, nutze ich eigentlich nur noch Write host, aber addiere ein "ERR:" oder "WRN:" oder "INF": am Anfang. Das könnte also wie folgt aussehen:

# Muster eines PowerShell Script
write-host "Script gestartet"
write-host " weniger wichtig"
write-host "  noch weniger wichtig"
write-host "WRN: Warnung, da passt was nicht"
write-host "ERR: Das ist ein echtes Problem"
write-host "Script beendet"

Ich wollte an meinen bestehenden Skripten eigentlich gar nicht ändern.

Mit dieser Vorarbeit habe ich die Grundlage für ein generisches Modul geschaffen, welches alle "Write-Host"-Aufrufe eines Skript einfängt und ggfls. weiter verarbeitet, in eine Datei schreibt oder z.B. per SYSLOG an eine andere Plattform meldet. Es sollte natürlich alle oder zumindest die wichtige Parameter von "Write-Host" verstehen und mitnehmen und vielleicht sogar einen "Mehrwert" daraus beziehen.

 

Das hier ist noch eine "Baustelle", denn das passende Modul ist noch nicht fertig.

Ich denke ich werde hier aber nicht weiter aktiv werden, sondern eine passende Erweiterung oder eben Write-Verbose nutzen.

Andere Libraries und Tools gibt es ja auch schon. Das Rad muss man ja nicht mehrfach erfinden

Gerade die "Log4Posh-Funktion" ist für Enterprise-Logging sehr interessant.

Weitere Links