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.

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.

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 umfangreiche, 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.

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. UNd 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 dre 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.

Mein "Write-Log"

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).

In PowerShell habe ich mich etwas schwerer getan, da es nicht so einfach war, Klassen zu entwickeln. Und selbst mit einer eigenen Debug-Klasse wäre es immer noch eine Menge Arbeit gewesen, die bestehenden Skripte umzubauen, damit Sie diese Klasse auch nutzen. Mir wäre es am liebsten gewesen, wenn ich die Funktion "Write-Host" einfach erweitern könnte. Und faszinierender weise geht das mit PowerShell sehr einfach. Ich kann bestehende Comandlets einfach durch eigenen Code überschreiben. Klar, dass ich an das original Commandlet dann nicht mehr so einfach heran komme. Wenn ich also etwas weiter auf den Bildschirm ausgeben will, muss ich mir meine eigenen Gedanken dazu machen. Das war aber noch nicht alles. Wenn schon, dann wollte ich schon den Skriptnamen und vielleicht noch die Funktion mit angeben. Ein Zeitstempel wäre auch nett und die Ausgabedatei könnte eine CSV-Datei mit Spalten zum Filtern sein. Vielleicht könnten einige Ausgaben auch noch im Eventlog landen und verschiedene Debug-Level wären auch nicht schlecht. Die Wunschliste könnte man weiter fortsetzen. 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
start-msxfaqlog .\logfile.txt

write-msxfaqlog "Script gestartet"

write-msxfaqlog " weniger wichtig"
write-msxfaqlog "  noch weniger wichtig"
write-msxfaqlog "WRN: Warnung, da passt was nicht"
write-msxfaqlog "ERR: Das ist ein echtes Problem"

write-msxfaqlog "Script beendet"

Ich wollte an meinen bestehenden Skripten eigentlich gar nicht ändern. Also habe ich mir überlegt, wie ich mit einem eigenen Modul einfach bei Bedarf die "Write-Host"-Aufgaben abfangen und in eigene Ziele leiten kann.

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