Skip to content

Commit

Permalink
Log MS-CorrelationId with each API request
Browse files Browse the repository at this point in the history 
The Windows Store Submission API returns a special
header named `MS-CorrelationId` with every API response.
This value can be used to correlate the request on their
end, which is necessary when needing to debug / investigate
problems with specific requests.

We now log this header value (to the Verbose channel) upon
each request currently being executed internally by
`Invoke-SBRestMethod`.

Previously, `Invoke-SBRestMethod` was a wrapper around
`Invoke-RestMethod`.  However, `Invoke-RestMethod` drops
headers that come from the response.  Therefore, it is now
moving to use `Invoke-WebRequest` (which `Invoke-RestMethod`
itself had been a wrapper on).

On success, it's quite easy to get accsess to the response headers.
Getting access to the headers in the failure scenario is a bit
more complicated.

Any failure in the request (400, 409, etc...) is considered a `WebException`.
That exception has a `Response` object with access to the headers.
When -NoStatus is being used, that exception is sent directly, making header
access easy.

However, in the asynchronous execution scenario (which is the default),
exceptions come back serialized within a `RemoteException`,
and `WebException` does not serialize its header collection.  This means
that we can't directly use the `WebException` if we want access to the
header value.  Instead, we do a catch within the execution of the asynchronous
job itself, and we'll throw a custom exception that is our own JSON object
which contains the specific data that we need to use in the true exception
handling.

With that, we can then unify our true exception handling, extract out the
information from the exception object into common local variables, and then
use the same codepath for handling the exception itself.

The net result is that we now uniformly report errors the exact same way,
and we log `MS-CorrelationId` in all success and failure scenarios.
  • Loading branch information
@HowardWolosky
HowardWolosky committed Mar 7, 2017
1 parent a81c4d7 commit 0b7dc94
Show file tree
Hide file tree
Showing 2 changed files with 123 additions and 48 deletions.
2 changes: 1 addition & 1 deletion StoreBroker/StoreBroker.psd1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@
CompanyName = 'Microsoft Corporation'
Copyright = 'Copyright (C) Microsoft Corporation. All rights reserved.'

ModuleVersion = '1.3.0'
ModuleVersion = '1.4.0'
Description = 'Provides command-line access to the Windows Store Submission REST API.'

RootModule = 'StoreIngestionApi'
Expand Down
169 changes: 122 additions & 47 deletions StoreBroker/StoreIngestionApi.psm1
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,10 @@ $script:keywordPendingCommit = 'PendingCommit'
$script:keywordRelease = 'Release'
$script:keywordPublished = 'Published'

# Special header added to Submission API responses that provides a unique ID
# that the Submission API team can use to trace back problems with a specific request.
$script:headerMSCorrelationId = 'MS-CorrelationId'

# Warning that is referenced in multiple places throughout the module.
# {0} will be replaced in context with the relevant command.
$script:manualPublishWarning = @"
Expand Down Expand Up @@ -1402,10 +1406,10 @@ function Invoke-SBRestMethod
{
<#
.SYNOPSIS
A wrapper around Invoke-RestMethod that understands the Store API.
A wrapper around Invoke-WebRequest that understands the Store API.
.DESCRIPTION
A very heavy wrapper around Invoke-RestMethod that understands the Store API and
A very heavy wrapper around Invoke-WebRequest that understands the Store API and
how to perform its operation with and without console status updates. It also
understands how to parse and handle errors from the REST calls.
Expand Down Expand Up @@ -1466,6 +1470,11 @@ function Invoke-SBRestMethod
Deletes the specified submission, but the request happens in the foreground and there is
no additional status shown to the user until a response is returned from the REST request.
.NOTES
This wraps Invoke-WebRequest as opposed to Invoke-RestMethod because we want access to the headers
that are returned in the response (specifically 'MS-CorrelationId') for logging purposes, and
Invoke-RestMethod drops those headers.
#>
[CmdletBinding(SupportsShouldProcess)]
[Diagnostics.CodeAnalysis.SuppressMessageAttribute("PSAvoidGlobalVars", "", Justification="We use global variables sparingly and intentionally for module configuration, and employ a consistent naming convention.")]
Expand Down Expand Up @@ -1546,7 +1555,7 @@ function Invoke-SBRestMethod

if ($NoStatus)
{
if ($PSCmdlet.ShouldProcess($url, "Invoke-RestMethod"))
if ($PSCmdlet.ShouldProcess($url, "Invoke-WebRequest"))
{
$params = @{}
$params.Add("Uri", $url)
Expand All @@ -1560,7 +1569,7 @@ function Invoke-SBRestMethod
$params.Add("Body", $bodyAsBytes)
}

$result = Invoke-RestMethod @params
$result = Invoke-WebRequest @params
if ($Method -eq 'delete')
{
Write-Log "Successfully removed." -Level Verbose
Expand All @@ -1574,7 +1583,11 @@ function Invoke-SBRestMethod
if ($PSCmdlet.ShouldProcess($jobName, "Start-Job"))
{
[scriptblock]$scriptBlock = {
param($Url, $method, $Headers, $Body)
param($Url, $method, $Headers, $Body, $HeaderName)

# Because this is running in a different PowerShell process, we need to
# redefine this script variable (for use within the exception)
$script:headerMSCorrelationId = $HeaderName

$params = @{}
$params.Add("Uri", $Url)
Expand All @@ -1588,10 +1601,29 @@ function Invoke-SBRestMethod
$params.Add("Body", $bodyAsBytes)
}

Invoke-RestMethod @params
try
{
Invoke-WebRequest @params
}
catch [System.Net.WebException]
{
# We need to access the CorrelationId header in the exception handling,
# but the actual *values* of the headers of a WebException don't get serialized
# when the RemoteException wraps it. To work around that, we'll extract the
# information that we actually care about *now*, and then we'll throw our own exception
# that is just a JSON object with the data that we'll later extract for processing in
# the main catch.
$ex = @{}
$ex.Message = $_.Exception.Message
$ex.StatusCode = $_.Exception.Response.StatusCode
$ex.StatusDescription = $_.Exception.Response.StatusDescription
$ex.CorrelationId = $_.Exception.Response.Headers[$script:headerMSCorrelationId]
$ex.InnerMessage = $_.ErrorDetails.Message
throw ($ex | ConvertTo-Json -Depth 20)
}
}

$null = Start-Job -Name $jobName -ScriptBlock $scriptBlock -Arg @($url, $Method, $headers, $Body)
$null = Start-Job -Name $jobName -ScriptBlock $scriptBlock -Arg @($url, $Method, $headers, $Body, $script:headerMSCorrelationId)

if ($PSCmdlet.ShouldProcess($jobName, "Wait-JobWithAnimation"))
{
Expand All @@ -1606,7 +1638,7 @@ function Invoke-SBRestMethod

if ($remoteErrors.Count -gt 0)
{
throw $remoteErrors[0].Exception
throw $remoteErrors[0].Exception
}

if ($Method -eq 'delete')
Expand All @@ -1615,6 +1647,12 @@ function Invoke-SBRestMethod
}
}

$correlationId = $result.Headers[$script:headerMSCorrelationId]
if (-not [String]::IsNullOrEmpty($correlationId))
{
Write-Log "$($script:headerMSCorrelationId): $correlationId" -Level Verbose
}

# Record the telemetry for this event.
$stopwatch.Stop()
if (-not [String]::IsNullOrEmpty($TelemetryEventName))
Expand All @@ -1623,69 +1661,106 @@ function Invoke-SBRestMethod
Set-TelemetryEvent -EventName $TelemetryEventName -Properties $localTelemetryProperties -Metrics $telemetryMetrics
}

return $result
$finalResult = $result.Content
try
{
$finalResult = $finalResult | ConvertFrom-Json
}
catch [ArgumentException]
{
# The content must not be JSON. We'll return the raw content result instead.
}

return $finalResult
}
catch [System.InvalidOperationException]
catch
{
# This type of exception occurs when using -NoStatus
# We only know how to handle WebExceptions, which will either come in "pure" when running with -NoStatus,
# or will come in as a RemoteException when running normally (since it's coming from the asynchronous Job).
$ex = $null
$message = $null
$statusCode = $null
$statusDescription = $null
$correlationId = $null
$innerMessage = $null

if ($_.Exception -is [System.Net.WebException])
{
$ex = $_.Exception
$message = $ex.Message
$statusCode = $ex.Response.StatusCode.value__ # Note that value__ is not a typo.
$statusDescription = $ex.Response.StatusDescription
$innerMessage = $_.ErrorDetails.Message
$correlationId = $ex.Response.Headers[$script:headerMSCorrelationId]

# Dig into the exception to get the Response details.
# Note that value__ is not a typo.
$output = @()
$statusCode = $_.Exception.Response.StatusCode.value__
if ($statusCode -eq 404)
}
elseif (($_.Exception -is [System.Management.Automation.RemoteException]) -and
($_.Exception.SerializedRemoteException.PSObject.TypeNames[0] -eq 'Deserialized.System.Management.Automation.RuntimeException'))
{
$output += "The item being removed could not be found."
$ex = $_.Exception
try
{
$deserialized = $ex.Message | ConvertFrom-Json
$message = $deserialized.Message
$statusCode = $deserialized.StatusCode
$statusDescription = $deserialized.StatusDescription
$innerMessage = $deserialized.InnerMessage
$correlationId = $deserialized.CorrelationId
}
catch [System.ArgumentException]
{
# Will be thrown if $ex.Message isn't JSON content
Write-Log $ex.Message -Level Error
Set-TelemetryException -Exception $ex -ErrorBucket $errorBucket -Properties $localTelemetryProperties
throw;
}
}
elseif ($statusCode -eq 409)
else
{
$output += "The item being removed was found, but could be deleted in its current state."
Write-Log $_.Exception.Message -Level Error
Set-TelemetryException -Exception $_.Exception -ErrorBucket $errorBucket -Properties $localTelemetryProperties
throw;
}

$output += "StatusCode: $($_.Exception.Response.StatusCode.value__)"
$output += "StatusDescription: $($_.Exception.Response.StatusDescription)"
$output += "$($_.ErrorDetails)"

Set-TelemetryException -Exception $_.Exception -ErrorBucket $errorBucket -Properties $localTelemetryProperties
Write-Log $($output -join [Environment]::NewLine) -Level Error
throw "Halt Execution"
}
catch [System.Management.Automation.RuntimeException]
{
# This type of exception occurs when NOT using -NoStatus

$output = @()
$output += "$($_.Exception.Message)"
if ($_.ErrorDetails.Message)
if (-not [string]::IsNullOrEmpty($statusCode))
{
$output += "$statusCode | $statusDescription"
}

$output += $message

if (-not [string]::IsNullOrEmpty($innerMessage))
{
try
{
$message = ($_.ErrorDetails.Message | ConvertFrom-Json)
if ($message -is [String])
$innerMessageJson = ($innerMessage | ConvertFrom-Json)
if ($innerMessageJson -is [String])
{
$output += $message
$output += $innerMessageJson
}
else
{
$output += "$($message.code) : $($message.message)"
if ($message.details)
$output += "$($innerMessageJson.code) : $($innerMessageJson.message)"
if ($innerMessageJson.details)
{
$output += "$($message.details | Format-Table | Out-String)"
$output += "$($innerMessageJson.details | Format-Table | Out-String)"
}
}
}
catch [ArgumentException]
catch [System.ArgumentException]
{
# Will be thrown if $_.ErrorDetails.Message isn't JSON content
$message = $_.ErrorDetails.Message
if ([String]::IsNullOrEmpty($message))
{
$output += $message
}
# Will be thrown if $innerMessage isn't JSON content
$output += $innerMessage
}
}

Set-TelemetryException -Exception $_.Exception -ErrorBucket $errorBucket -Properties $localTelemetryProperties
if (-not [String]::IsNullOrEmpty($correlationId))
{
Write-Log "$($script:headerMSCorrelationId): $correlationId" -Level Verbose
}

Set-TelemetryException -Exception $ex -ErrorBucket $errorBucket -Properties $localTelemetryProperties
Write-Log $($output -join [Environment]::NewLine) -Level Error
throw "Halt Execution"
}
Expand Down

0 comments on commit 0b7dc94

Please sign in to comment.