Building a Better Get-SQLErrorLog
Back in July of 2016, Microsoft made an exciting announcement: they were finally (finally!) adding new cmdlets to the SQL Server PowerShell provider. Along with some new management cmdlets around SQL Server Agent and Always Encrypted, there was one that caught my eye immediately: Get-SQLErrorlog. I’ve always wanted an easier way to get error logs from SQL Server, and this new cmdlet seemed perfect. I downloaded the update and I gave it a whirl.
At first, everything looked pretty promising: I give the cmdlet an instance (either via name or path) and it returns error log entries. There’s also support for time ranges via the -Before ,-To , and -Timespan parameters. It sounded too good to be true.
It turns out that it kind of was.
The current cmdlet
If my QA servers had a Facebook page, their relationship status would be “it’s complicated.” They always have plenty of issues, so they have lots of error logs to parse. I fired up the new module (Import-Module sqlserver ) and gave it a whirl:
Get-SQLErrorLog -ServerInstance QASERVER
And I was greeted by a deluge of text in my console:
That’s the end of the output chain, and that number underneath the last line is the result of a Stopwatch class; I wrapped the cmdlet in it and used it to output the run time in milliseconds (which comes out to just a hair under 42 minutes to return 158MB of log files). It looks like it’s putting out an object of some type so I changed my command to put the results in a variable and then I wanted to see what the object looked like:
$ErrorLogs = Get-SQLErrorLog -ServerInstance QASERVER $ErrorLogs | Get-Member
That’s quite an object we have there. The good news was that it was a lot faster: it didn’t have to pipe the entire contents to my screen. But the resulting object was pretty big. And it had one pretty big drawback: I couldn’t filter on error types, severity or message. I mean, I could… but I have to parse the Text property.
But that’s not all. I was curious about how the cmdlet was figuring out what error logs to use, or where they were located. So I fired up an extended event session to look for it. Here’s what I found:
You can’t see all the text data from the statement fields, but it’s collecting a bunch of information from some dynamic management views and returning the info from the client. If you’re looking at that and wondering why I think it’s a big deal, here’s why: can you think of a good reason why you’d want to look at your error logs? I can: when my server’s down! I can’t use this cmdlet if the server is unreachable. That’s a pretty big swing-and-a-miss, at least to me.
Dreaming a little bigger
It doesn’t have to be so bad, though, because we can make it better. In my mind, my perfect error log cmdlet should:
- Be usable when a SQL Server instance is down, and
- Be relatively quick, and
- Parse error messages by number, severity, and state, and
- Incorporate date/time range filtering, and
- Return an object
What’s that, you say? You want to solve each of these and write our own, better cmdlet? I got you, fam. At the bottom of this blog post you’ll find my code, and you can skip ahead if you don’t care about the “hows” or “whys” of what you’ll be looking at.
Where my log files at (y’all)?
First things first: we need a better way to determine where the logs files for a SQL instance are located without the need to query SQL server. Fortunately, there’s a way to do that: each time SQL Server starts, it writes information to the Windows Event Log with event ID 17111, as shown below.
There’s a handy cmdlet included with Windows named, you guessed it, Get-EventLog that allows us to filter on Event IDs. We can use it to find the event IDs in question, and parse out the path where the logs are being stored. In this case, my QA server drops them on a disk named K: and in the SQLData\Logs with a filename of ERRORLOG. We can do that with one handy line of PowerShell:
$ErrorLogPathFromEventLog = ((Get-Eventlog -LogName Application | where-object {$_.EventID -eq 17111 -and $_.Source -eq "SQLSERVER"} | Select -First 1).Message -replace "Logging SQL Server messages in file '","") -replace "'.",""
That line of code does quite a bit: it connects to the event log of our local PC and finds all events with an ID of 17111 and a source of “SQLSERVER.” It then gets the very first one in the list (the most recent startup) and strips out the first part of the message and the trailing single quote and period, leaving us with the path and filename of the latest error log.
This is good, but it’s not good enough: we still need to be able to run the Get-EventLog cmdlet on a target server, and we need to make sure we can filter on the correct instance of SQL Server (if we’re running a named instance, or if we’re running multiple instances). To do that, our script will make use of the Invoke-Command which will let us execute a command on remote computer. It will also take our server instance parameter and use that to filter the event log event further. You can see this in action in the code at the bottom of this post.
Gotta go fast
Once we have our error logs, the next thing we have to do is load and parse the text. Unfortunately, this isn’t something that regular old PowerShell is great at. That’s because a lot of PowerShell cmdlets that read files have pipeline support. That means every line of text it reads, it passes through the pipeline. This is INCREDIBLY slow. But we can turn that behavior off, and you can see the difference for yourself. The following two lines of code do the same exact thing, but the gulf in performance is breathtaking.
Get-Content -Path C:\temp\somefilewithlinesoftext.txt Get-Content -Path C:\temp\somefilewithlinesoftext.txt -ReadCount 0
Why the difference? The second line uses a parameter of Get-Content called -Readcount . It controls how many lines of text are passed through the pipeline at one time. A value of zero says “pass everything at once,” which is a lot faster.
Matchmaker, matchmaker
Okay, so we’ve got the location of our error logs and we’ve got a method to quickly retrieve them. Now for the tricky part: parsing them. Text parsing in PowerShell isn’t great; there aren’t a lot of native libraries that do anything special with large collections of text. Once our error logs are read from disk, we need to find specific errors in the error log and parse them out. We could go one line at a time, but that would be painfully slow. There’s one way that does provide a pretty nifty way of finding particular lines of text: a regular expression.
The regular expression I wrote will find all lines of text in your error logs that look like this:
2016-10-02 15:33:19.79 spid55 Error: 14151, Severity: 18, State: 1. 2016-10-02 15:33:19.79 spid55 Replication-Replication Transaction-Log Reader Subsystem: agent QASERVER-DATABASE-2 failed. The process could not execute 'sp_repldone/sp_replcounters' on 'QASERVER'.
So to match those lines, I’m using the Select-String cmdlet and using the -Pattern parameter to pass along a regular expression:
$matchedLines = $AllContent | Select-String -Pattern '((\w+): (\d+)[,\.]\s?){3}'
(Note: If you don’t use regular expressions often, that line probably doesn’t make a lot of sense. I don’t use them very often, but I’m familiar with them. That line right there? That was the hardest part of writing this script. There are a ton of great regular expression editors and tutorials out there. They’ll do a better job of teaching you about them than I can.)
Our matching pattern will find all the lines that match this text, and return the line numbers that contain them. And it’s relatively fast; not instant, but not terribly long either. And once we have the lines that match this text, the SQL Server error logs always put the message of the error on the following line. We just have to use the line numbers of the error numbers, add one, and boom, we get our errors with messages that we can write to an object.
Divide and conquer
Once we know the line numbers, it just becomes yet another text parsing exercise. If you’ve done any text parsing in PowerShell, you might know it’s slow. So then the question becomes: how can we speed it up without loading custom libraries or modules? The same way SQL Server breaks up expensive queries: we’ll multi-thread it.
Multi-threading in PowerShell is not something I have done much of, but there’s a couple different ways to do it. To do it “properly,” we need to use runspaces. The simplest way to describe a runspace is that you write a script of code, you give it to a runspace, pass it some parameters, and it goes and runs it. The hard part comes after you tell it to run. You need to monitor the runspace to see if it completes, you need to retrieve the results of the processing, and you need to dismiss it when you’re done. None of this is done automatically (short of closing your PowerShell session, that is).
Complicating things is our need to not just make one runspace, but to make multiple. Here’s a snippet of code that creates the runspaces:
$Runspace = [runspacefactory]::CreateRunspace() $PowerShell = [powershell]::Create().AddScript($FileReaderScriptBlock).AddArgument($e.FullName).AddArgument($InvokeCommandParamters) $PowerShell.Runspace = $Runspace $PowerShellObjects += $PowerShell
We create a runspace, then we add some properties: the script we want to run (a previously declared scriptblock variable), and any arguments that need passed to it. In this section, I’m also collecting all my runspaces into one object so I can start, stop, collect, and dispose of them easier. Then we tell the runspaces to well, run. We kick them off like this:
$PowerShellObject.Runspace.Open() [void]$Jobs.Add(($PowerShellObject.BeginInvoke()))
Now we wait and monitor. The loop below will iterate indefinitely until they all the runspaces say they are done:
Do {
Start-Sleep -Seconds 1
} While ($jobs.IsCompleted -contains $false)
And once they’re done, we need to collect the returned results and dispose of them:
$Data = $PowerShellObject.EndInvoke($Jobs[$Counter]) $AllContent += $Data.Content $Results += $Data $Counter++ $PowerShellObject.Runspace.Dispose() $PowerShellObject.Dispose()
Putting it all together
I’ve written enough; you probably want to just see the code. I have plenty of -Verbose support in the script and some stopwatch support to report on how long it takes it process each step.
[cmdletbinding()]
param(
[Parameter(Mandatory = $true)]
[string]$servername,
[Parameter(Mandatory = $false)]
[string]$instanceName = "DEFAULT",
[Parameter(Mandatory = $false)]
[string]$From = "1/1/1970 00:00:00",
[Parameter(Mandatory = $false)]
[string]$To,
[Parameter(Mandatory = $false)]
[System.Management.Automation.CredentialAttribute()]
$Credential,
[Parameter(Mandatory = $false)]
[int]$maxThreads
)
begin
{
$FileReaderScriptBlock = {
Param (
[string] $filepath,
[hashtable] $splat
)
$RemoteCommandScriptBlock = {
param (
[string] $filepath
)
Get-Content $filepath -ReadCount 0
}
$Content = Invoke-Command @splat -scriptblock $RemoteCommandScriptBlock -ArgumentList $filePath
$RunResult = [pscustomobject] @{
FileName = $filepath
ContentCount = $Content.Count
Content = $Content
ScriptToRun = $RemoteCommandScriptBlock
}
Return $RunResult
}
$FileParserScriptBlock = {
Param (
[array] $fileContents,
[array] $lineNumbers
)
$ErrorLogEntries = New-Object -typename System.Collections.ArrayList
For ($l = 0; $l -lt $lineNumbers.Count; $l++) {
$LineNumber = $lineNumbers[$l].LineNumber
$line = $fileContents[$LineNumber-1] -replace '\s+', ' '
$parsed = $line.split(' ')
$logErrorNumber = $parsed[4] -replace ',',''
$logSeverity = $parsed[6] -replace ',',''
$LogState = $parsed[8] -replace '\.',''
$line = $fileContents[$LineNumber] -replace '\s+', ' '
$parsed = $line.split(' ')
$eventTime = Get-Date -Date ($parsed[0] + ' ' + $parsed[1])
if ($parsed[2] -ne "Server") {
$spid = ($parsed[2] -replace 'spid','') -replace 's',''
} else {
$Spid = $null
}
$message = $line.Substring($parsed[0].Length + $parsed[1].Length + $parsed[2].length + 3)
$ErrorLogEvent = [pscustomobject] @{
EventTime = $eventTime
Spid = $spid
Message = $message
ErrorNumber = $logErrorNumber
Severity = $logSeverity
State = $LogState
}
$ErrorLogEntries.Add($ErrorLogEvent)
}
$RunResult = New-Object PSObject -Property @{
ErrorLogObjects = $ErrorLogEntries
}
Return $RunResult
}
}
process
{
$eventSource = "MSSQLSERVER"
if ($instancename -ne "DEFAULT") {
$eventSource = "MSSQL$" + $instanceName
}
if (!$to) {
$to = Get-Date
Write-Verbose "Settting to to $to"
}
$InvokeCommandParamters = @{
'ComputerName'=$servername;
}
if ($Credential) {
$InvokeCommandParamters.Add('Credential',$Credential)
}
Write-Verbose "Server Name: $servername"
Write-Verbose "Looking for SQL Server instance information for service $eventsource"
$ErrorLogPathFromEventLog = ((Invoke-Command @InvokeCommandParamters -ScriptBlock {param ($eventSource) Get-Eventlog -LogName Application | where-object {$_.EventID -eq 17111 -and $_.Source -eq $eventSource}} -ArgumentList $eventSource | Select -First 1).Message -replace "Logging SQL Server messages in file '","") -replace "'.",""
$errorLogPath = $ErrorLogPathFromEventLog.Substring(0,$ErrorLogPathFromEventLog.LastIndexOf("\"))
$errorLogFileName = $ErrorLogPathFromEventLog.Substring($ErrorLogPathFromEventLog.LastIndexOf("\")+1)
Write-Verbose "SQL Server Error Log Path: $errorlogpath"
$ErrorLogs = Invoke-Command @InvokeCommandParamters -ScriptBlock {param ($ErrorLogPath, $ErrorLogFileName) Get-ChildItem -Path $ErrorLogPath | Where-Object {$_.Name -like "$ErrorLogFileName*"}} -ArgumentList $errorlogpath, $errorLogFileName
$LastErrorLog = $ErrorLogs | Where-Object {$_.LastWriteTime -le $from} | Sort-Object -Property LastWriteTime -Descending | Select -First 1
if ($to -ge ($ErrorLogs | Sort-Object -Property LastWritTime | Select -First 1).LastWriteTime) {
$FirstErrorLog = $ErrorLogs | Sort-Object -Property LastWritTime | Select -First 1
} else {
$FirstErrorLog = $ErrorLogs | Where-Object {$_.LastWriteTime -ge $to} | Sort-Object -Property LastWriteTime | Select -First 1
}
$ErrorLogs = $ErrorLogs | Where-Object {$_.LastWriteTime -ge $LastErrorLog.LastWriteTime -and $_.LastWriteTime -le $FirstErrorLog.LastWriteTime} | Sort-Object -Property LastWriteTime
$fileNumber = 0
$jobs = New-Object -typename System.Collections.ArrayList
$PowerShellObjects = New-Object -typename System.Collections.ArrayList
$Results = @()
ForEach ($ErrorLog in $ErrorLogs)
{
$Runspace = [runspacefactory]::CreateRunspace()
$PowerShell = [powershell]::Create().AddScript($FileReaderScriptBlock).AddArgument($ErrorLog.FullName).AddArgument($InvokeCommandParamters)
$PowerShell.Runspace = $Runspace
[void]$PowerShellObjects.Add($PowerShell)
}
ForEach ($PowerShellObject in $PowerShellObjects)
{
$PowerShellObject.Runspace.Open()
[void]$Jobs.Add(($PowerShellObject.BeginInvoke()))
}
Write-Verbose "All files added, waiting for threads to complete"
$StopWatch = [System.Diagnostics.Stopwatch]::StartNew()
Do
{
Start-Sleep -Seconds 1
} While ($jobs.IsCompleted -contains $false)
Write-Verbose "All threads completed!"
$StopWatch.Stop()
$FileReaderDuration = $StopWatch.Elapsed.TotalMilliseconds
Write-Verbose "$FileReaderDuration milliseconds to read all the files"
$Counter = 0
$AllContent = $null
ForEach ($PowerShellObject in $PowerShellObjects)
{
$Data = $PowerShellObject.EndInvoke($Jobs[$Counter])
$AllContent += $Data.Content
$Results += $Data
$Counter++
$PowerShellObject.Runspace.Dispose()
$PowerShellObject.Dispose()
}
Write-Verbose "Matching error lines..."
$matchedLines = $AllContent | Select-String -Pattern '((\w+): (\d+)[,\.]\s?){3}'
$matchedLinesTotal = $matchedLines.Length
$remainder = $matchedLinesTotal % 8
$setSize = ($matchedLinesTotal - $remainder) / 8
$jobs = New-Object -typename System.Collections.ArrayList
$PowerShellObjects = New-Object -typename System.Collections.ArrayList
$Results = @()
Write-Verbose "There are $matchedLinesTotal to parse"
for ($x = 0; $x -lt 8; $x++) {
$min = $setSize * $x
$max = $min + ($setSize - 1)
$subSet = $matchedLines[$min..$max]
Write-Verbose "Chunking $min to $max..."
$Runspace = [runspacefactory]::CreateRunspace()
$m = $matchedLines[$min..$max]
$PowerShell = [powershell]::Create().AddScript($FileParserScriptBlock).AddArgument($AllContent).AddArgument($subSet)
$PowerShell.Runspace = $Runspace
[void]$PowerShellObjects.Add($PowerShell)
}
if ($remainder -gt 0) {
$min = $max + 1
$max = $matchedLinesTotal
$subSet = $matchedLines[$min..$max]
Write-Verbose "Chunking remainder $min to $max..."
$Runspace = [runspacefactory]::CreateRunspace()
$PowerShell = [powershell]::Create().AddScript($FileParserScriptBlock).AddArgument($AllContent).AddArgument($subSet)
$PowerShell.Runspace = $Runspace
[void]$PowerShellObjects.Add($PowerShell)
}
ForEach ($PowerShellObject in $PowerShellObjects)
{
$PowerShellObject.Runspace.Open()
[void]$Jobs.Add(($PowerShellObject.BeginInvoke()))
}
$StopWatch = [System.Diagnostics.Stopwatch]::StartNew()
Write-Verbose "All files chunks chunked, waiting for threads to complete"
Do
{
Write-Verbose "Waiting..."
Start-Sleep -Seconds 2
} While ($jobs.IsCompleted -contains $false)
Write-Verbose "All threads completed!"
$StopWatch.Stop()
$FileParserDuration = $StopWatch.Elapsed.TotalMilliseconds
Write-Verbose "$FileParserDuration milliseconds to parse all the chunks"
$Errors = New-Object -typename System.Collections.ArrayList
$Counter = 0
ForEach ($PowerShellObject in $PowerShellObjects)
{
$Data = $PowerShellObject.EndInvoke($Jobs[$Counter])
[void]$Errors.Add($Data.ErrorLogObjects)
$Counter++
$PowerShellObject.Runspace.Dispose()
$PowerShellObject.Dispose()
}
}
end
{
return $Errors
$Results = $null
$AllContent = $null
}
As for use, here’s a concrete example: I’m going to collect the error logs from my QA server, and filter for all failed logins (error number 18456). Simple, effective, and it’s a great way to find all failed logins for an instance:
$ErrorLogs = .\Get-SQLErrorLog.ps1 -servername QA-SALESSQL-01 -Verbose
$ErrorLogs | Where-Object {$_.ErrorNumber -eq 18456}
Final notes and thanks
Is this code perfect? Goodness, no. I could continue to improve upon it; for example, I’m passing the entire contents of the file to each runspace to parse. That’s expensive. The script also doesn’t return informational messages and instead only parses out actual errors. I wrote it to demonstrate what I feel is a more useful implementation of an error log parser. I am also omitting the ability to filter for error numbers/severity/state numbers in the cmdlet itself and instead am relying on the user to filter it.
Ultimately though, I’m hoping that this kind of functionality (and the need for it, in my opinion) is something that we’ll see incorporated into future versions of the Get-SQLErrorLog cmdlet. I’m hoping that this gets enough exposure for that to happen.
There are probably a multitude of ways this script can be improved, and you can even help by contributing. I put this code out on my Github for you to download and play with it. It comes with the standard warning, as always: <Deep breath> “Don’t just run code you found on the internet in production. Test it first, understand it, and then see it can meet your needs before going to production. I can’t assume responsibility if you mess up your servers.”
This script was a long time coming; I’ve been writing it on and off for a couple months now. I couldn’t have finalized it, though, without the help of some very special people:
- Paul Bahler (@paulbahler), who I work with and is amazing programmer, a good friend, and also currently smells like blueberries. He also was my go-to resource for my regular expression work.
- Aaron Nelson (@sqlvariant) for a great extra set of eyes on a code review and suggesting we get this up to Microsoft so they can improve the existing functionality of the code. I’m hoping that happens!
- Chrissy LaMaire (@cl), who helped give me great feedback on my code (and style) before publishing the final version of the code. She also makes excellent steak frites.
And a big “thank you” for reading! What do you think? Is this functionality useful to you too? Head down to the comments and let me know.
Pingback: A Better Get-SQLErrorLog – Curated SQL