Logging Archives - Wolffhaven45 Blog

Anyone who has administered a little SCCM in their time, would be be familiar with the tool CMTrace or SMSTrace. CMTrace is a tool that comes with System Center Configuration Manager. It allows you to view the myriad of logs files that SCCM generates in a consistent and easy to read format. Being used to the log format that CMTrace generates, I thought it would be a great idea to use that format for logging Powershell script actions and errors.

I hunted around the web and found a few versions of a log function using CMTRace. The best implementation that I found was from Russ Slaten at the System Center Blog site. It works really well but I wanted to add some different functionality.

CMTrace.exe is part of the System Center 2012 R2 Configuration Manager Toolkit, which I believe anyone can download. If you have System Center Configuration Manager installed in your environment, you can also grab it from the \\”SiteServer”\Program Files\Microsoft Configuration Manager\tools\cmtrace.exe.

There are a few different use cases for when logging is handy: -

Running Powershell scripts as Scheduled Tasks.
Auditing automation centrally in a team environment.
The output of a log could be used as part of change management processes.
Debugging locally and remotely

I’ll start off by posting the script. Below I’ll go into some information that might help in using the script.

**NOTE: This has only been tested on Powershell v5.0. The information stream is a new feature of Powershell v5.0.**

Here is the script: -

#Requires -version 5.0 
Function Write-CMTraceLog{
########################################################################################################## 
<# 
.SYNOPSIS 
   Write to a log file in a format that takes advantage of the CMTrace.exe log viewer that comes with SCCM.
.DESCRIPTION 
   Output strings to a log file that is formatted for use with CMTRace.exe and also writes back to the host.
   The severity of the logged line can be set as: 
        2-Error
        3-Warning
        4-Verbose
        5-Debug
        6-Information
   Warnings will be highlighted in yellow. Errors are highlighted in red. 
   The tools to view the log: 
   SMS Trace - http://www.microsoft.com/en-us/download/details.aspx?id=18153 
   CM Trace - https://www.microsoft.com/en-us/download/details.aspx?id=50012 or the Installation directory on Configuration Manager 2012 Site Server - <Install Directory>\tools\ 
.EXAMPLE 
Try{
    Get-Process -Name DoesnotExist -ea stop
}
Catch{
    Write-CMTraceLog -Logfile "C:\output\logfile.log -Message $Error[0] -Type Error
}
   This will write a line to the logfile.log file in c:\output\logfile.log. It will state the errordetails in the log file 
   and highlight the line in Red. It will also write back to the host in a friendlier red on black message than
   the normal error record.
.EXAMPLE
 $VerbosePreference = Continue
 Write-CMTraceLog -Message "This is a verbose message." -Type Verbose
   This example will write a verbose entry into the log file and also write back to the host. The Write-CMTraceLog will obey
   the preference variables.
.EXAMPLE
Write-CMTraceLog -Message "This is an informational message" -Type Information -WritebacktoHost:$false
    This example will write the informational message to the log but not back to the host.
.EXAMPLE
Function Test{
    [cmdletbinding()]
    Param()
    Write-CMTraceLog -Message "This is a verbose message" -Type Verbose
}
Test -Verbose
This example shows how to use write-cmtracelog inside a function and then call the function with the -verbose switch.
The write-cmtracelog function will then print the verbose message.
.NOTES
    ##########
    Change Log
    ##########
    v1.5 - 12-03-2015 - Found bug with Error writing back to host twice. Fixed.
    ##########
    v1.4 - 12-03-2015 - Found bug with Warning writebackto host duplicating warning error message.
                        Fixed.
    ##########
    v1.3 - 23-12-2015 - Commented out line 224 and 249 as it was causing a duplicaton of the message.
    ##########
    v1.2 - Fixed inheritance of preference variables from child scopes finally!! Changed from using
            using get-variable -scope 1 (which doesn't work when a script modules calls a function:
            See this Microsoft Connect bug https://connect.microsoft.com/PowerShell/feedback/details/1606119.)
            Anyway now now i use the $PSCmdlet.GetVariableValue('VerbosePreference') command and it works.
    ##########
    v1.1 - Found a bug with the get-variable scope. Need to refer to 2 parent scopes for the writebacktohost to work.
         - Changed all Get-Variable commands to use Scope 2, instead of Scope 1.
    ##########
    v1.0 - Script Created
#> 
########################################################################################################## 
    #Define and validate parameters 
    [CmdletBinding()] 
    Param( 
        #Path to the log file 
        [parameter(Mandatory=$False)]      
        [String]$Logfile = "$Env:Temp\powershell-cmtrace.log",
        #The information to log 
        [parameter(Mandatory=$True)] 
        $Message,
        #The severity (Error, Warning, Verbose, Debug, Information)
        [parameter(Mandatory=$True)]
        [ValidateSet('Warning','Error','Verbose','Debug', 'Information')] 
        [String]$Type,
        #Write back to the console or just to the log file. By default it will write back to the host.
        [parameter(Mandatory=$False)]
        [switch]$WriteBackToHost = $True
    )#Param
    #Get the info about the calling script, function etc
    $callinginfo = (Get-PSCallStack)[1]
    #Set Source Information
    $Source = (Get-PSCallStack)[1].Location
    #Set Component Information
    $Component = (Get-Process -Id $PID).ProcessName
    #Set PID Information
    $ProcessID = $PID
    #Obtain UTC offset 
    $DateTime = New-Object -ComObject WbemScripting.SWbemDateTime  
    $DateTime.SetVarDate($(Get-Date)) 
    $UtcValue = $DateTime.Value 
    $UtcOffset = $UtcValue.Substring(21, $UtcValue.Length - 21)
    #Set the order 
    switch($Type){
           'Warning' {$Severity = 2}#Warning
             'Error' {$Severity = 3}#Error
           'Verbose' {$Severity = 4}#Verbose
             'Debug' {$Severity = 5}#Debug
       'Information' {$Severity = 6}#Information
    }#Switch
    #Switch statement to write out to the log and/or back to the host.
    switch ($severity){
        2{
            #Warning
            #Write the log entry in the CMTrace Format.
             $logline = `
            "<![LOG[$($($Type.ToUpper()) + ": " +  $message)]LOG]!>" +`
            "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
            "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
            "component=`"$Component`" " +`
            "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
            "type=`"$Severity`" " +`
            "thread=`"$ProcessID`" " +`
            "file=`"$Source`">";
            $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;
            #Write back to the host if $Writebacktohost is true.
            if(($WriteBackToHost) -and ($Type -eq 'Warning')){
                Switch($PSCmdlet.GetVariableValue('WarningPreference')){
                    'Continue' {$WarningPreference = 'Continue';Write-Warning -Message "$Message";$WarningPreference=''}
                    'Stop' {$WarningPreference = 'Stop';Write-Warning -Message "$Message";$WarningPreference=''}
                    'Inquire' {$WarningPreference ='Inquire';Write-Warning -Message "$Message";$WarningPreference=''}
                    'SilentlyContinue' {}
                }
            }
        }#Warning
        3{  
            #Error
            #This if statement is to catch the two different types of errors that may come through. A normal terminating exception will have all the information that is needed, if it's a user generated error by using Write-Error,
            #then the else statment will setup all the information we would like to log.   
            if($Message.exception.Message){                
                if(($WriteBackToHost)-and($Type -eq 'Error')){                                        
                    #Write the log entry in the CMTrace Format.
                    $logline = `
                    "<![LOG[$($($Type.ToUpper()) + ": " +  "$([String]$Message.exception.message)`r`r" + `
                    "`nCommand: $($Message.InvocationInfo.MyCommand)" + `
                    "`nScriptName: $($Message.InvocationInfo.Scriptname)" + `
                    "`nLine Number: $($Message.InvocationInfo.ScriptLineNumber)" + `
                    "`nColumn Number: $($Message.InvocationInfo.OffsetInLine)" + `
                    "`nLine: $($Message.InvocationInfo.Line)")]LOG]!>" +`
                    "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
                    "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
                    "component=`"$Component`" " +`
                    "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
                    "type=`"$Severity`" " +`
                    "thread=`"$ProcessID`" " +`
                    "file=`"$Source`">"
                    $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;
                    #Write back to Host
                    Switch($PSCmdlet.GetVariableValue('ErrorActionPreference')){
                        'Stop'{$ErrorActionPreference = 'Stop';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Stop';$ErrorActionPreference=''}
                        'Inquire'{$ErrorActionPreference = 'Inquire';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Inquire';$ErrorActionPreference=''}
                        'Continue'{$ErrorActionPreference = 'Continue';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");$ErrorActionPreference=''}
                        'Suspend'{$ErrorActionPreference = 'Suspend';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Suspend';$ErrorActionPreference=''}
                        'SilentlyContinue'{}
                    }
                }
                else{                   
                    #Write the log entry in the CMTrace Format.
                    $logline = `
                    "<![LOG[$($($Type.ToUpper()) + ": " +  "$([String]$Message.exception.message)`r`r" + `
                    "`nCommand: $($Message.InvocationInfo.MyCommand)" + `
                    "`nScriptName: $($Message.InvocationInfo.Scriptname)" + `
                    "`nLine Number: $($Message.InvocationInfo.ScriptLineNumber)" + `
                    "`nColumn Number: $($Message.InvocationInfo.OffsetInLine)" + `
                    "`nLine: $($Message.InvocationInfo.Line)")]LOG]!>" +`
                    "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
                    "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
                    "component=`"$Component`" " +`
                    "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
                    "type=`"$Severity`" " +`
                    "thread=`"$ProcessID`" " +`
                    "file=`"$Source`">"
                    $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;
                }
            }
            else{
                if(($WriteBackToHost)-and($type -eq 'Error')){
                    [System.Exception]$Exception = $Message
                    [String]$ErrorID = 'Custom Error'
                    [System.Management.Automation.ErrorCategory]$ErrorCategory = [Management.Automation.ErrorCategory]::WriteError
                    #[System.Object]$Message
                    $ErrorRecord = New-Object Management.automation.errorrecord ($Exception,$ErrorID,$ErrorCategory,$Message)
                    $Message = $ErrorRecord
                    #Write the log entry
                    $logline = `
                        "<![LOG[$($($Type.ToUpper()) + ": " +  "$([String]$Message.exception.message)`r`r" + `
                        "`nFunction: $($Callinginfo.FunctionName)" + `
                        "`nScriptName: $($Callinginfo.Scriptname)" + `
                        "`nLine Number: $($Callinginfo.ScriptLineNumber)" + `
                        "`nColumn Number: $($callinginfo.Position.StartColumnNumber)" + `
                        "`nLine: $($Callinginfo.Position.StartScriptPosition.Line)")]LOG]!>" +`
                        "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
                        "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
                        "component=`"$Component`" " +`
                        "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
                        "type=`"$Severity`" " +`
                        "thread=`"$ProcessID`" " +`
                        "file=`"$Source`">"
                        $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;
                    #Write back to Host.
                    Switch($PSCmdlet.GetVariableValue('ErrorActionPreference')){
                            'Stop'{$ErrorActionPreference = 'Stop';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Stop';$ErrorActionPreference=''}
                            'Inquire'{$ErrorActionPreference = 'Inquire';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Inquire';$ErrorActionPreference=''}
                            'Continue'{$ErrorActionPreference = 'Continue';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message 2>&1 > $null;$ErrorActionPreference=''}
                            'Suspend'{$ErrorActionPreference = 'Suspend';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Suspend';$ErrorActionPreference=''}
                            'SilentlyContinue'{}
                        }
                }
                else{
                    #Write the Log Entry
                    [System.Exception]$Exception = $Message
                    [String]$ErrorID = 'Custom Error'
                    [System.Management.Automation.ErrorCategory]$ErrorCategory = [Management.Automation.ErrorCategory]::WriteError
                    #[System.Object]$Message
                    $ErrorRecord = New-Object Management.automation.errorrecord ($Exception,$ErrorID,$ErrorCategory,$Message)
                    $Message = $ErrorRecord
                    #Write the log entry
                    $logline = `
                        "<![LOG[$($($Type.ToUpper())+ ": " +  "$([String]$Message.exception.message)`r`r" + `
                        "`nFunction: $($Callinginfo.FunctionName)" + `
                        "`nScriptName: $($Callinginfo.Scriptname)" + `
                        "`nLine Number: $($Callinginfo.ScriptLineNumber)" + `
                        "`nColumn Number: $($Callinginfo.Position.StartColumnNumber)" + `
                        "`nLine: $($Callinginfo.Position.StartScriptPosition.Line)")]LOG]!>" +`
                        "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
                        "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
                        "component=`"$Component`" " +`
                        "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
                        "type=`"$Severity`" " +`
                        "thread=`"$ProcessID`" " +`
                        "file=`"$Source`">"
                        $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;
                }                
            }   
        }#Error
        4{  
            #Verbose
            #Write the Log Entry
            $logline = `
            "<![LOG[$($($Type.ToUpper()) + ": " +  $message)]LOG]!>" +`
            "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
            "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
            "component=`"$Component`" " +`
            "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
            "type=`"$severity`" " +`
            "thread=`"$processid`" " +`
            "file=`"$source`">";
            $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile; 
            #Write Back to Host
            if(($WriteBackToHost) -and ($Type -eq 'Verbose')){
                Switch ($PSCmdlet.GetVariableValue('VerbosePreference')) {
                    'Continue' {$VerbosePreference = 'Continue'; Write-Verbose -Message "$Message";$VerbosePreference = ''}
                    'Inquire' {$VerbosePreference = 'Inquire'; Write-Verbose -Message "$Message";$VerbosePreference = ''}
                    'Stop' {$VerbosePreference = 'Stop'; Write-Verbose -Message "$Message";$VerbosePreference = ''}
                }
            }              
        }#Verbose
        5{  
            #Debug
            #Write the Log Entry
            $logline = `
            "<![LOG[$($($Type.ToUpper()) + ": " +  $message)]LOG]!>" +`
            "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
            "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
            "component=`"$Component`" " +`
            "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
            "type=`"$severity`" " +`
            "thread=`"$processid`" " +`
            "file=`"$source`">";
            $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;  
            #Write Back to the Host.                              
            if(($WriteBackToHost) -and ($Type -eq 'Debug')){
                Switch ($PSCmdlet.GetVariableValue('DebugPreference')){
                    'Continue' {$DebugPreference = 'Continue'; Write-Debug -Message "$Message";$DebugPreference = ''}
                    'Inquire' {$DebugPreference = 'Inquire'; Write-Debug -Message "$Message";$DebugPreference = ''}
                    'Stop' {$DebugPreference = 'Stop'; Write-Debug -Message "$Message";$DebugPreference = ''}
                }
            } 
        }#Debug
        6{  
            #Information
            #Write entry to the logfile.
            $logline = `
            "<![LOG[$($($Type.ToUpper()) + ": " + $message)]LOG]!>" +`
            "<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`
            "date=`"$(Get-Date -Format M-d-yyyy)`" " +`
            "component=`"$Component`" " +`
            "context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`
            "type=`"$severity`" " +`
            "thread=`"$processid`" " +`
            "file=`"$source`">";            
            $logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;
            #Write back to the host.
            if(($WriteBackToHost) -and ($Type -eq 'Information')){
                Switch ($PSCmdlet.GetVariableValue('InformationPreference')){
                    'Continue' {$InformationPreference = 'Continue'; Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}
                    'Inquire' {$InformationPreference = 'Inquire'; Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}
                    'Stop' {$InformationPreference = 'Stop'; Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}
                    'Suspend' {$InformationPreference = 'Suspend';Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}
                }
            }
        }#Information
    }#Switch
}#Function v1.5 - 12-03-2016

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

164

165

166

167

168

169

170

171

172

173

174

175

176

177

178

179

180

181

182

183

184

185

186

187

188

189

190

191

192

193

194

195

196

197

198

199

200

201

202

203

204

205

206

207

208

209

210

211

212

213

214

215

216

217

218

219

220

221

222

223

224

225

226

227

228

229

230

231

232

233

234

235

236

237

238

239

240

241

242

243

244

245

246

247

248

249

250

251

252

253

254

255

256

257

258

259

260

261

262

263

264

265

266

267

268

269

270

271

272

273

274

275

276

277

278

279

280

281

282

283

284

285

286

287

288

289

290

291

292

293

294

295

296

297

298

299

300

301

302

303

304

305

306

307

308

309

310

311

312

313

314

315

316

317

318

319

320

321

322

323

324

325

326

327

328

329

330

331

332

333

334

335

336

337

338

339

340

341

342

343

344

345

346

347

348

349

350

351

352

353

354

355

356

357

358

359

360

361

362

363

364

365

366

367

368

369

#Requires -version 5.0

Function Write-CMTraceLog{

##########################################################################################################

.SYNOPSIS

Write to a log file in a format that takes advantage of the CMTrace.exe log viewer that comes with SCCM.

.DESCRIPTION

Output strings to a log file that is formatted for use with CMTRace.exe and also writes back to the host.

The severity of the logged line can be set as:

2-Error

3-Warning

4-Verbose

5-Debug

6-Information

Warnings will be highlighted in yellow. Errors are highlighted in red.

The tools to view the log:

SMS Trace - http://www.microsoft.com/en-us/download/details.aspx?id=18153

CM Trace - https://www.microsoft.com/en-us/download/details.aspx?id=50012 or the Installation directory on Configuration Manager 2012 Site Server - <Install Directory>\tools\

.EXAMPLE

Try{

Get-Process -Name DoesnotExist -ea stop

}

Catch{

Write-CMTraceLog -Logfile "C:\output\logfile.log -Message $Error[0] -Type Error

}

This will write a line to the logfile.log file in c:\output\logfile.log. It will state the errordetails in the log file

and highlight the line in Red. It will also write back to the host in a friendlier red on black message than

the normal error record.

.EXAMPLE

$VerbosePreference = Continue

Write-CMTraceLog -Message "This is a verbose message." -Type Verbose

This example will write a verbose entry into the log file and also write back to the host. The Write-CMTraceLog will obey

the preference variables.

.EXAMPLE

Write-CMTraceLog -Message "This is an informational message" -Type Information -WritebacktoHost:$false

This example will write the informational message to the log but not back to the host.

.EXAMPLE

Function Test{

[cmdletbinding()]

Param()

Write-CMTraceLog -Message "This is a verbose message" -Type Verbose

}

Test -Verbose

This example shows how to use write-cmtracelog inside a function and then call the function with the -verbose switch.

The write-cmtracelog function will then print the verbose message.

.NOTES

##########

Change Log

##########

v1.5 - 12-03-2015 - Found bug with Error writing back to host twice. Fixed.

##########

v1.4 - 12-03-2015 - Found bug with Warning writebackto host duplicating warning error message.

Fixed.

##########

v1.3 - 23-12-2015 - Commented out line 224 and 249 as it was causing a duplicaton of the message.

##########

v1.2 - Fixed inheritance of preference variables from child scopes finally!! Changed from using

using get-variable -scope 1 (which doesn't work when a script modules calls a function:

See this Microsoft Connect bug https://connect.microsoft.com/PowerShell/feedback/details/1606119.)

Anyway now now i use the $PSCmdlet.GetVariableValue('VerbosePreference') command and it works.

##########

v1.1 - Found a bug with the get-variable scope. Need to refer to 2 parent scopes for the writebacktohost to work.

- Changed all Get-Variable commands to use Scope 2, instead of Scope 1.

##########

v1.0 - Script Created

##########################################################################################################

#Define and validate parameters

[CmdletBinding()]

Param(

#Path to the log file

[parameter(Mandatory=$False)]

[String]$Logfile = "$Env:Temp\powershell-cmtrace.log",

#The information to log

[parameter(Mandatory=$True)]

$Message,

#The severity (Error, Warning, Verbose, Debug, Information)

[parameter(Mandatory=$True)]

[ValidateSet('Warning','Error','Verbose','Debug', 'Information')]

[String]$Type,

#Write back to the console or just to the log file. By default it will write back to the host.

[parameter(Mandatory=$False)]

[switch]$WriteBackToHost = $True

)#Param

#Get the info about the calling script, function etc

$callinginfo = (Get-PSCallStack)[1]

#Set Source Information

$Source = (Get-PSCallStack)[1].Location

#Set Component Information

$Component = (Get-Process -Id $PID).ProcessName

#Set PID Information

$ProcessID = $PID

#Obtain UTC offset

$DateTime = New-Object -ComObject WbemScripting.SWbemDateTime

$DateTime.SetVarDate($(Get-Date))

$UtcValue = $DateTime.Value

$UtcOffset = $UtcValue.Substring(21, $UtcValue.Length - 21)

#Set the order

switch($Type){

'Warning' {$Severity = 2}#Warning

'Error' {$Severity = 3}#Error

'Verbose' {$Severity = 4}#Verbose

'Debug' {$Severity = 5}#Debug

'Information' {$Severity = 6}#Information

}#Switch

#Switch statement to write out to the log and/or back to the host.

switch ($severity){

#Warning

#Write the log entry in the CMTrace Format.

$logline = `

"<![LOG[$($($Type.ToUpper()) + ": " + $message)]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$Severity`" " +`

"thread=`"$ProcessID`" " +`

"file=`"$Source`">";

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

#Write back to the host if $Writebacktohost is true.

if(($WriteBackToHost) -and ($Type -eq 'Warning')){

Switch($PSCmdlet.GetVariableValue('WarningPreference')){

'Continue' {$WarningPreference = 'Continue';Write-Warning -Message "$Message";$WarningPreference=''}

'Stop' {$WarningPreference = 'Stop';Write-Warning -Message "$Message";$WarningPreference=''}

'Inquire' {$WarningPreference ='Inquire';Write-Warning -Message "$Message";$WarningPreference=''}

'SilentlyContinue' {}

}

}#Warning

#Error

#This if statement is to catch the two different types of errors that may come through. A normal terminating exception will have all the information that is needed, if it's a user generated error by using Write-Error,

#then the else statment will setup all the information we would like to log.

if($Message.exception.Message){

if(($WriteBackToHost)-and($Type -eq 'Error')){

#Write the log entry in the CMTrace Format.

$logline = `

"<![LOG[$($($Type.ToUpper()) + ": " + "$([String]$Message.exception.message)`r`r" + `

"`nCommand: $($Message.InvocationInfo.MyCommand)" + `

"`nScriptName: $($Message.InvocationInfo.Scriptname)" + `

"`nLine Number: $($Message.InvocationInfo.ScriptLineNumber)" + `

"`nColumn Number: $($Message.InvocationInfo.OffsetInLine)" + `

"`nLine: $($Message.InvocationInfo.Line)")]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$Severity`" " +`

"thread=`"$ProcessID`" " +`

"file=`"$Source`">"

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

#Write back to Host

Switch($PSCmdlet.GetVariableValue('ErrorActionPreference')){

'Stop'{$ErrorActionPreference = 'Stop';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Stop';$ErrorActionPreference=''}

'Inquire'{$ErrorActionPreference = 'Inquire';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Inquire';$ErrorActionPreference=''}

'Continue'{$ErrorActionPreference = 'Continue';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");$ErrorActionPreference=''}

'Suspend'{$ErrorActionPreference = 'Suspend';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Suspend';$ErrorActionPreference=''}

'SilentlyContinue'{}

}

else{

#Write the log entry in the CMTrace Format.

$logline = `

"<![LOG[$($($Type.ToUpper()) + ": " + "$([String]$Message.exception.message)`r`r" + `

"`nCommand: $($Message.InvocationInfo.MyCommand)" + `

"`nScriptName: $($Message.InvocationInfo.Scriptname)" + `

"`nLine Number: $($Message.InvocationInfo.ScriptLineNumber)" + `

"`nColumn Number: $($Message.InvocationInfo.OffsetInLine)" + `

"`nLine: $($Message.InvocationInfo.Line)")]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$Severity`" " +`

"thread=`"$ProcessID`" " +`

"file=`"$Source`">"

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

}

else{

if(($WriteBackToHost)-and($type -eq 'Error')){

[System.Exception]$Exception = $Message

[String]$ErrorID = 'Custom Error'

[System.Management.Automation.ErrorCategory]$ErrorCategory = [Management.Automation.ErrorCategory]::WriteError

#[System.Object]$Message

$ErrorRecord = New-Object Management.automation.errorrecord ($Exception,$ErrorID,$ErrorCategory,$Message)

$Message = $ErrorRecord

#Write the log entry

$logline = `

"<![LOG[$($($Type.ToUpper()) + ": " + "$([String]$Message.exception.message)`r`r" + `

"`nFunction: $($Callinginfo.FunctionName)" + `

"`nScriptName: $($Callinginfo.Scriptname)" + `

"`nLine Number: $($Callinginfo.ScriptLineNumber)" + `

"`nColumn Number: $($callinginfo.Position.StartColumnNumber)" + `

"`nLine: $($Callinginfo.Position.StartScriptPosition.Line)")]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$Severity`" " +`

"thread=`"$ProcessID`" " +`

"file=`"$Source`">"

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

#Write back to Host.

Switch($PSCmdlet.GetVariableValue('ErrorActionPreference')){

'Stop'{$ErrorActionPreference = 'Stop';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Stop';$ErrorActionPreference=''}

'Inquire'{$ErrorActionPreference = 'Inquire';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Inquire';$ErrorActionPreference=''}

'Continue'{$ErrorActionPreference = 'Continue';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message 2>&1 > $null;$ErrorActionPreference=''}

'Suspend'{$ErrorActionPreference = 'Suspend';$Host.Ui.WriteErrorLine("ERROR: $([String]$Message.Exception.Message)");Write-Error $Message -ErrorAction 'Suspend';$ErrorActionPreference=''}

'SilentlyContinue'{}

}

else{

#Write the Log Entry

[System.Exception]$Exception = $Message

[String]$ErrorID = 'Custom Error'

[System.Management.Automation.ErrorCategory]$ErrorCategory = [Management.Automation.ErrorCategory]::WriteError

#[System.Object]$Message

$ErrorRecord = New-Object Management.automation.errorrecord ($Exception,$ErrorID,$ErrorCategory,$Message)

$Message = $ErrorRecord

#Write the log entry

$logline = `

"<![LOG[$($($Type.ToUpper())+ ": " + "$([String]$Message.exception.message)`r`r" + `

"`nFunction: $($Callinginfo.FunctionName)" + `

"`nScriptName: $($Callinginfo.Scriptname)" + `

"`nLine Number: $($Callinginfo.ScriptLineNumber)" + `

"`nColumn Number: $($Callinginfo.Position.StartColumnNumber)" + `

"`nLine: $($Callinginfo.Position.StartScriptPosition.Line)")]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$Severity`" " +`

"thread=`"$ProcessID`" " +`

"file=`"$Source`">"

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

}

}#Error

#Verbose

#Write the Log Entry

$logline = `

"<![LOG[$($($Type.ToUpper()) + ": " + $message)]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$severity`" " +`

"thread=`"$processid`" " +`

"file=`"$source`">";

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

#Write Back to Host

if(($WriteBackToHost) -and ($Type -eq 'Verbose')){

Switch ($PSCmdlet.GetVariableValue('VerbosePreference')) {

'Continue' {$VerbosePreference = 'Continue'; Write-Verbose -Message "$Message";$VerbosePreference = ''}

'Inquire' {$VerbosePreference = 'Inquire'; Write-Verbose -Message "$Message";$VerbosePreference = ''}

'Stop' {$VerbosePreference = 'Stop'; Write-Verbose -Message "$Message";$VerbosePreference = ''}

}

}#Verbose

#Debug

#Write the Log Entry

$logline = `

"<![LOG[$($($Type.ToUpper()) + ": " + $message)]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$severity`" " +`

"thread=`"$processid`" " +`

"file=`"$source`">";

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

#Write Back to the Host.

if(($WriteBackToHost) -and ($Type -eq 'Debug')){

Switch ($PSCmdlet.GetVariableValue('DebugPreference')){

'Continue' {$DebugPreference = 'Continue'; Write-Debug -Message "$Message";$DebugPreference = ''}

'Inquire' {$DebugPreference = 'Inquire'; Write-Debug -Message "$Message";$DebugPreference = ''}

'Stop' {$DebugPreference = 'Stop'; Write-Debug -Message "$Message";$DebugPreference = ''}

}

}#Debug

#Information

#Write entry to the logfile.

$logline = `

"<![LOG[$($($Type.ToUpper()) + ": " + $message)]LOG]!>" +`

"<time=`"$(Get-Date -Format HH:mm:ss.fff)$($UtcOffset)`" " +`

"date=`"$(Get-Date -Format M-d-yyyy)`" " +`

"component=`"$Component`" " +`

"context=`"$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)`" " +`

"type=`"$severity`" " +`

"thread=`"$processid`" " +`

"file=`"$source`">";

$logline | Out-File -Append -Encoding utf8 -FilePath $Logfile;

#Write back to the host.

if(($WriteBackToHost) -and ($Type -eq 'Information')){

Switch ($PSCmdlet.GetVariableValue('InformationPreference')){

'Continue' {$InformationPreference = 'Continue'; Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}

'Inquire' {$InformationPreference = 'Inquire'; Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}

'Stop' {$InformationPreference = 'Stop'; Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}

'Suspend' {$InformationPreference = 'Suspend';Write-Information -Message "INFORMATION: $Message";$InformationPreference = ''}

}

}#Information

}#Switch

}#Function v1.5 - 12-03-2016

I’ve included a help file inline to help with calling the function.

Where does the log file get created?

The function by default will log to $Env:temp\powershell-cmtrace.log. You can however pass a file location to the function if you would like to the log file in a different location.

What does the output look like on the host?

Here is an example.

Why does Error only log one line back to the host, where is all the ErrorRecord informaiton?

I wanted to write back to the host in a consistent fashion. The error record is still there I’m just not passing it back to the host. The full error record gets put in the log file and you can view that information by clicking on the Error entry and looking at the window down the bottom of CMTrace. Also, you can still access the error information in the host by using the $Error variable. If it were the last error you would access it by using the first index of the $Error variable. eg. $Error[0].

What does the output to the log file look like?

It looks like this. Notice the Error information is in the box down the bottom.

I don’t want to see the output on the host, I just want it to log in the CMTrace format.

There is a parameter switch called WriteBackToHost. By default it’s set to True, but if you don’t want to see the output then set this to false.

How do I call this function?

To call this function, either dot source it, run it from ISE and then call it, put it in your profile or pop it in a module and Bob is your uncle.

Gimme some examples of how to use the Write-CMTracelog function.

Here are some examples of how you would use this advanced function that are in the help section of the function.

Examples:

The below example shows how to output a verbose message.

Write-CMTraceLog -Message 'This is a verbose message' -Type Verbose

1	Write-CMTraceLog -Message 'This is a verbose message' -Type Verbose

This example shows how to use the Preference variables with the Write-CMTracelog function. It should obey any preference variables that are set in the same scope from where the function has been called.

 $VerbosePreference = Continue
 Write-CMTraceLog -Message "This is a verbose message." -Type Verbose

1 2	$VerbosePreference = Continue Write-CMTraceLog -Message "This is a verbose message." -Type Verbose

This example shows how to use the function with a terminating error by using the $Error variable in the message parameter.

Try{
    Get-Process -Name DoesnotExist -ea stop
}
Catch{
    Write-CMTraceLog -Logfile "C:\output\logfile.log -Message $Error[0] -Type Error
}

Try{

Get-Process -Name DoesnotExist -ea stop

}

Catch{

Write-CMTraceLog -Logfile "C:\output\logfile.log -Message $Error[0] -Type Error

}

Hope this function helps you out. Feel free to use and modify to suit your needs.

Sources:

http://blogs.msdn.com/b/rslaten/archive/2014/07/28/logging-in-cmtrace-format-from-powershell.aspx
https://www.microsoft.com/en-us/download/details.aspx?id=50012
http://blogs.technet.com/b/heyscriptingguy/archive/2015/07/04/weekend-scripter-welcome-to-the-powershell-information-stream.aspx

Tag Archives: Logging

Writing CMTrace format Log files with Powershell

Where does the log file get created?

What does the output look like on the host?

Why does Error only log one line back to the host, where is all the ErrorRecord informaiton?

I don’t want to see the output on the host, I just want it to log in the CMTrace format.

How do I call this function?

Gimme some examples of how to use the Write-CMTracelog function.

Recent Posts

Recent Comments

Archives

Categories

Meta