Skip to content

Commit c92d8a6

Browse files
HowardWoloskyHowardWolosky
authored
Fix potential call depth overflow error when retrying a 202 response (#294)
GitHub will return back a `202` response when the result for the query is not yet ready. GitHub requests that we "give the job a few moments to complete, and then submit the request again." We already had the configuration value `RetryDelaySeconds` which covered how many seconds we would sleep before trying the request again. We tried the request again via a recursive call to `Invoke-GHRestMethod`. It turns out that there's something going on with GitHub right now, and trying to get contributor statistics for a completely new repository never returns back a 200, even after 145 retry attempts over 72 minutes. That many recursive calls ends up causing a call depth overflow exception with PowerShell. While this scenario should be an edge-case, nonetheless it seems better to remove the possibility of this error from occurring by modifying the retry logic to be a loop rather than a recursive call. I've also added a new configuration value: `MaximumRetriesWhenResultNotReady` to help control and limit the number of retries that we'll attempt in this situation, ultimately throwing an exception if the retry limit is exceeded without a 200 response. Finally, I've disabled the `When getting Github Repository Contributors with Statistics` test until the problem is fixed on the GitHub end. I've disabled the test by commenting the test out vs using the disable keyword to avoid the Pester failure for disabled tests, and I've opened a [support issue](https://github.community/t/unable-to-retrieve-contributor-statistics-for-a-brand-new-repo/136658) on this problem.
1 parent c066149 commit c92d8a6

File tree

3 files changed

+201
-170
lines changed

3 files changed

+201
-170
lines changed

‎GitHubConfiguration.ps1

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -135,6 +135,12 @@ function Set-GitHubConfiguration
135135
.PARAMETER LogTimeAsUtc
136136
If specified, all times logged will be logged as UTC instead of the local timezone.
137137
138+
.PARAMETER MaximumRetriesWhenResultNotReady
139+
Some API requests may take time for GitHub to gather the results, and in the interim,
140+
a 202 response is returned. This value indicates the maximum number of times that the
141+
query will be retried before giving up and failing. The amount of time between each of
142+
these requests is controlled by the RetryDelaySeconds configuration value.
143+
138144
.PARAMETER MultiRequestProgressThreshold
139145
Some commands may require sending multiple requests to GitHub. In some situations,
140146
getting the entirety of the request might take 70+ requests occurring over 20+ seconds.
@@ -145,6 +151,8 @@ function Set-GitHubConfiguration
145151
146152
.PARAMETER RetryDelaySeconds
147153
The number of seconds to wait before retrying a command again after receiving a 202 response.
154+
The number of times that a retry will occur is controlled by the
155+
MaximumRetriesWhenResultNotReady configuration value.
148156
149157
.PARAMETER StateChangeDelaySeconds
150158
The number of seconds to wait before returning the result after executing a command that
@@ -227,6 +235,8 @@ function Set-GitHubConfiguration
227235

228236
[switch] $LogTimeAsUtc,
229237

238+
[int] $MaximumRetriesWhenResultNotReady,
239+
230240
[int] $MultiRequestProgressThreshold,
231241

232242
[int] $RetryDelaySeconds,
@@ -320,6 +330,7 @@ function Get-GitHubConfiguration
320330
'LogProcessId',
321331
'LogRequestBody',
322332
'LogTimeAsUtc',
333+
'MaximumRetriesWhenResultNotReady',
323334
'MultiRequestProgressThreshold',
324335
'RetryDelaySeconds',
325336
'StateChangeDelaySeconds',
@@ -678,6 +689,7 @@ function Import-GitHubConfiguration
678689
'logProcessId' = $false
679690
'logRequestBody' = $false
680691
'logTimeAsUtc' = $false
692+
'maximumRetriesWhenResultNotReady' = 30
681693
'multiRequestProgressThreshold' = 10
682694
'retryDelaySeconds' = 30
683695
'stateChangeDelaySeconds' = 0

‎GitHubCore.ps1

Lines changed: 157 additions & 142 deletions
Original file line numberDiff line numberDiff line change
@@ -196,6 +196,10 @@ function Invoke-GHRestMethod
196196
$errorBucket = $TelemetryEventName
197197
}
198198

199+
# Handling retries for 202
200+
$numRetriesAttempted = 0
201+
$maxiumRetriesPermitted = Get-GitHubConfiguration -Name 'MaximumRetriesWhenResultNotReady'
202+
199203
# Since we have retry logic, we won't create a new stopwatch every time,
200204
# we'll just always continue the existing one...
201205
$stopwatch.Start()
@@ -261,182 +265,193 @@ function Invoke-GHRestMethod
261265

262266
try
263267
{
264-
Write-Log -Message $Description -Level Verbose
265-
Write-Log -Message "Accessing [$Method] $url [Timeout = $(Get-GitHubConfiguration -Name WebRequestTimeoutSec))]" -Level Verbose
266-
267-
$result = $null
268-
$params = @{}
269-
$params.Add("Uri", $url)
270-
$params.Add("Method", $Method)
271-
$params.Add("Headers", $headers)
272-
$params.Add("UseDefaultCredentials", $true)
273-
$params.Add("UseBasicParsing", $true)
274-
$params.Add("TimeoutSec", (Get-GitHubConfiguration -Name WebRequestTimeoutSec))
275-
if ($PSBoundParameters.ContainsKey('InFile')) { $params.Add('InFile', $InFile) }
276-
if (-not [String]::IsNullOrWhiteSpace($outFile)) { $params.Add('OutFile', $outFile) }
277-
278-
if (($Method -in $ValidBodyContainingRequestMethods) -and (-not [String]::IsNullOrEmpty($Body)))
268+
while ($true) # infinite loop for handling the 202 retry, but we'll either exit via a return, or throw an exception if retry limit exceeded.
279269
{
280-
$bodyAsBytes = [System.Text.Encoding]::UTF8.GetBytes($Body)
281-
$params.Add("Body", $bodyAsBytes)
282-
Write-Log -Message "Request includes a body." -Level Verbose
283-
if (Get-GitHubConfiguration -Name LogRequestBody)
270+
Write-Log -Message $Description -Level Verbose
271+
Write-Log -Message "Accessing [$Method] $url [Timeout = $(Get-GitHubConfiguration -Name WebRequestTimeoutSec))]" -Level Verbose
272+
273+
$result = $null
274+
$params = @{}
275+
$params.Add("Uri", $url)
276+
$params.Add("Method", $Method)
277+
$params.Add("Headers", $headers)
278+
$params.Add("UseDefaultCredentials", $true)
279+
$params.Add("UseBasicParsing", $true)
280+
$params.Add("TimeoutSec", (Get-GitHubConfiguration -Name WebRequestTimeoutSec))
281+
if ($PSBoundParameters.ContainsKey('InFile')) { $params.Add('InFile', $InFile) }
282+
if (-not [String]::IsNullOrWhiteSpace($outFile)) { $params.Add('OutFile', $outFile) }
283+
284+
if (($Method -in $ValidBodyContainingRequestMethods) -and (-not [String]::IsNullOrEmpty($Body)))
284285
{
285-
Write-Log -Message $Body -Level Verbose
286+
$bodyAsBytes = [System.Text.Encoding]::UTF8.GetBytes($Body)
287+
$params.Add("Body", $bodyAsBytes)
288+
Write-Log -Message "Request includes a body." -Level Verbose
289+
if (Get-GitHubConfiguration -Name LogRequestBody)
290+
{
291+
Write-Log -Message $Body -Level Verbose
292+
}
286293
}
287-
}
288294

289-
# Disable Progress Bar in function scope during Invoke-WebRequest
290-
$ProgressPreference = 'SilentlyContinue'
295+
# Disable Progress Bar in function scope during Invoke-WebRequest
296+
$ProgressPreference = 'SilentlyContinue'
291297

292-
[Net.ServicePointManager]::SecurityProtocol=[Net.SecurityProtocolType]::Tls12
298+
[Net.ServicePointManager]::SecurityProtocol=[Net.SecurityProtocolType]::Tls12
293299

294-
$result = Invoke-WebRequest @params
300+
$result = Invoke-WebRequest @params
295301

296-
if ($Method -eq 'Delete')
297-
{
298-
Write-Log -Message "Successfully removed." -Level Verbose
299-
}
302+
if ($Method -eq 'Delete')
303+
{
304+
Write-Log -Message "Successfully removed." -Level Verbose
305+
}
300306

301-
# Record the telemetry for this event.
302-
$stopwatch.Stop()
303-
if (-not [String]::IsNullOrEmpty($TelemetryEventName))
304-
{
305-
$telemetryMetrics = @{ 'Duration' = $stopwatch.Elapsed.TotalSeconds }
306-
Set-TelemetryEvent -EventName $TelemetryEventName -Properties $localTelemetryProperties -Metrics $telemetryMetrics
307-
}
307+
# Record the telemetry for this event.
308+
$stopwatch.Stop()
309+
if (-not [String]::IsNullOrEmpty($TelemetryEventName))
310+
{
311+
$telemetryMetrics = @{ 'Duration' = $stopwatch.Elapsed.TotalSeconds }
312+
Set-TelemetryEvent -EventName $TelemetryEventName -Properties $localTelemetryProperties -Metrics $telemetryMetrics
313+
}
308314

309-
$finalResult = $result.Content
310-
try
311-
{
312-
if ($Save)
315+
$finalResult = $result.Content
316+
try
313317
{
314-
$finalResult = Get-Item -Path $outFile
318+
if ($Save)
319+
{
320+
$finalResult = Get-Item -Path $outFile
321+
}
322+
else
323+
{
324+
$finalResult = $finalResult | ConvertFrom-Json
325+
}
315326
}
316-
else
327+
catch [InvalidOperationException]
317328
{
318-
$finalResult = $finalResult | ConvertFrom-Json
329+
# In some cases, the returned data might have two different keys of the same characters
330+
# but different casing (this can happen with gists with two files named 'a.txt' and 'A.txt').
331+
# PowerShell 6 introduced the -AsHashtable switch to work around this issue, but this
332+
# module wants to be compatible down to PowerShell 4, so we're unable to use that feature.
333+
Write-Log -Message 'The returned object likely contains keys that differ only in casing. Unable to convert to an object. Returning the raw JSON as a fallback.' -Level Warning
334+
$finalResult = $finalResult
335+
}
336+
catch [ArgumentException]
337+
{
338+
# The content must not be JSON (which is a legitimate situation).
339+
# We'll return the raw content result instead.
340+
# We do this unnecessary assignment to avoid PSScriptAnalyzer's PSAvoidUsingEmptyCatchBlock.
341+
$finalResult = $finalResult
319342
}
320-
}
321-
catch [InvalidOperationException]
322-
{
323-
# In some cases, the returned data might have two different keys of the same characters
324-
# but different casing (this can happen with gists with two files named 'a.txt' and 'A.txt').
325-
# PowerShell 6 introduced the -AsHashtable switch to work around this issue, but this
326-
# module wants to be compatible down to PowerShell 4, so we're unable to use that feature.
327-
Write-Log -Message 'The returned object likely contains keys that differ only in casing. Unable to convert to an object. Returning the raw JSON as a fallback.' -Level Warning
328-
$finalResult = $finalResult
329-
}
330-
catch [ArgumentException]
331-
{
332-
# The content must not be JSON (which is a legitimate situation).
333-
# We'll return the raw content result instead.
334-
# We do this unnecessary assignment to avoid PSScriptAnalyzer's PSAvoidUsingEmptyCatchBlock.
335-
$finalResult = $finalResult
336-
}
337343

338-
if ((-not $Save) -and (-not (Get-GitHubConfiguration -Name DisableSmarterObjects)))
339-
{
340-
# In the case of getting raw content from the repo, we'll end up with a large object/byte
341-
# array which isn't convertible to a smarter object, but by _trying_ we'll end up wasting
342-
# a lot of time. Let's optimize here by not bothering to send in something that we
343-
# know is definitely not convertible ([int32] on PS5, [long] on PS7).
344-
if (($finalResult -isnot [Object[]]) -or
345-
(($finalResult.Count -gt 0) -and
346-
($finalResult[0] -isnot [int]) -and
347-
($finalResult[0] -isnot [long])))
344+
if ((-not $Save) -and (-not (Get-GitHubConfiguration -Name DisableSmarterObjects)))
345+
{
346+
# In the case of getting raw content from the repo, we'll end up with a large object/byte
347+
# array which isn't convertible to a smarter object, but by _trying_ we'll end up wasting
348+
# a lot of time. Let's optimize here by not bothering to send in something that we
349+
# know is definitely not convertible ([int32] on PS5, [long] on PS7).
350+
if (($finalResult -isnot [Object[]]) -or
351+
(($finalResult.Count -gt 0) -and
352+
($finalResult[0] -isnot [int]) -and
353+
($finalResult[0] -isnot [long])))
354+
{
355+
$finalResult = ConvertTo-SmarterObject -InputObject $finalResult
356+
}
357+
}
358+
359+
if ($result.Headers.Count -gt 0)
348360
{
349-
$finalResult = ConvertTo-SmarterObject -InputObject $finalResult
361+
$links = $result.Headers['Link'] -split ','
362+
$nextLink = $null
363+
$nextPageNumber = 1
364+
$numPages = 1
365+
$since = 0
366+
foreach ($link in $links)
367+
{
368+
if ($link -match '<(.*page=(\d+)[^\d]*)>; rel="next"')
369+
{
370+
$nextLink = $Matches[1]
371+
$nextPageNumber = [int]$Matches[2]
372+
}
373+
elseif ($link -match '<(.*since=(\d+)[^\d]*)>; rel="next"')
374+
{
375+
# Special case scenario for the users endpoint.
376+
$nextLink = $Matches[1]
377+
$since = [int]$Matches[2]
378+
$numPages = 0 # Signifies an unknown number of pages.
379+
}
380+
elseif ($link -match '<.*page=(\d+)[^\d]+rel="last"')
381+
{
382+
$numPages = [int]$Matches[1]
383+
}
384+
}
350385
}
351-
}
352386

353-
if ($result.Headers.Count -gt 0)
354-
{
355-
$links = $result.Headers['Link'] -split ','
356-
$nextLink = $null
357-
$nextPageNumber = 1
358-
$numPages = 1
359-
$since = 0
360-
foreach ($link in $links)
387+
$resultNotReadyStatusCode = 202
388+
if ($result.StatusCode -eq $resultNotReadyStatusCode)
361389
{
362-
if ($link -match '<(.*page=(\d+)[^\d]*)>; rel="next"')
390+
$retryDelaySeconds = Get-GitHubConfiguration -Name RetryDelaySeconds
391+
392+
if ($Method -ne 'Get')
393+
{
394+
# We only want to do our retry logic for GET requests...
395+
# We don't want to repeat PUT/PATCH/POST/DELETE.
396+
Write-Log -Message "The server has indicated that the result is not yet ready (received status code of [$($result.StatusCode)])." -Level Warning
397+
}
398+
elseif ($retryDelaySeconds -le 0)
363399
{
364-
$nextLink = $Matches[1]
365-
$nextPageNumber = [int]$Matches[2]
400+
Write-Log -Message "The server has indicated that the result is not yet ready (received status code of [$($result.StatusCode)]), however the module is currently configured to not retry in this scenario (RetryDelaySeconds is set to 0). Please try this command again later." -Level Warning
366401
}
367-
elseif ($link -match '<(.*since=(\d+)[^\d]*)>; rel="next"')
402+
elseif ($numRetriesAttempted -lt $maxiumRetriesPermitted)
368403
{
369-
# Special case scenario for the users endpoint.
370-
$nextLink = $Matches[1]
371-
$since = [int]$Matches[2]
372-
$numPages = 0 # Signifies an unknown number of pages.
404+
$numRetriesAttempted++
405+
$localTelemetryProperties['RetryAttempt'] = $numRetriesAttempted
406+
Write-Log -Message "The server has indicated that the result is not yet ready (received status code of [$($result.StatusCode)]). Will retry in [$retryDelaySeconds] seconds. $($maxiumRetriesPermitted - $numRetriesAttempted) retries remaining." -Level Warning
407+
Start-Sleep -Seconds ($retryDelaySeconds)
408+
continue # loop back and try this again
373409
}
374-
elseif ($link -match '<.*page=(\d+)[^\d]+rel="last"')
410+
else
375411
{
376-
$numPages = [int]$Matches[1]
412+
$message = "Request still not ready after $numRetriesAttempted retries. Retry limit has been reached as per configuration value 'MaximumRetriesWhenResultNotReady'"
413+
Write-Log -Message $message -Level Error
414+
throw $message
377415
}
378416
}
379-
}
380-
381-
$resultNotReadyStatusCode = 202
382-
if ($result.StatusCode -eq $resultNotReadyStatusCode)
383-
{
384-
$retryDelaySeconds = Get-GitHubConfiguration -Name RetryDelaySeconds
385417

386-
if ($Method -ne 'Get')
418+
# Allow for a delay after a command that may result in a state change in order to
419+
# increase the reliability of the UT's which attempt multiple successive state change
420+
# on the same object.
421+
$stateChangeDelaySeconds = $(Get-GitHubConfiguration -Name 'StateChangeDelaySeconds')
422+
$stateChangeMethods = @('Delete', 'Post', 'Patch', 'Put')
423+
if (($stateChangeDelaySeconds -gt 0) -and ($Method -in $stateChangeMethods))
387424
{
388-
# We only want to do our retry logic for GET requests...
389-
# We don't want to repeat PUT/PATCH/POST/DELETE.
390-
Write-Log -Message "The server has indicated that the result is not yet ready (received status code of [$($result.StatusCode)])." -Level Warning
425+
Start-Sleep -Seconds $stateChangeDelaySeconds
391426
}
392-
elseif ($retryDelaySeconds -le 0)
427+
428+
if ($ExtendedResult)
393429
{
394-
Write-Log -Message "The server has indicated that the result is not yet ready (received status code of [$($result.StatusCode)]), however the module is currently configured to not retry in this scenario (RetryDelaySeconds is set to 0). Please try this command again later." -Level Warning
430+
$finalResultEx = @{
431+
'result' = $finalResult
432+
'statusCode' = $result.StatusCode
433+
'requestId' = $result.Headers['X-GitHub-Request-Id']
434+
'nextLink' = $nextLink
435+
'nextPageNumber' = $nextPageNumber
436+
'numPages' = $numPages
437+
'since' = $since
438+
'link' = $result.Headers['Link']
439+
'lastModified' = $result.Headers['Last-Modified']
440+
'ifNoneMatch' = $result.Headers['If-None-Match']
441+
'ifModifiedSince' = $result.Headers['If-Modified-Since']
442+
'eTag' = $result.Headers['ETag']
443+
'rateLimit' = $result.Headers['X-RateLimit-Limit']
444+
'rateLimitRemaining' = $result.Headers['X-RateLimit-Remaining']
445+
'rateLimitReset' = $result.Headers['X-RateLimit-Reset']
446+
}
447+
448+
return ([PSCustomObject] $finalResultEx)
395449
}
396450
else
397451
{
398-
Write-Log -Message "The server has indicated that the result is not yet ready (received status code of [$($result.StatusCode)]). Will retry in [$retryDelaySeconds] seconds." -Level Warning
399-
Start-Sleep -Seconds ($retryDelaySeconds)
400-
return (Invoke-GHRestMethod @PSBoundParameters)
452+
return $finalResult
401453
}
402454
}
403-
404-
# Allow for a delay after a command that may result in a state change in order to
405-
#increase the reliability of the UT's which attempt multiple successive state change
406-
# on the same object.
407-
$stateChangeDelaySeconds = $(Get-GitHubConfiguration -Name 'StateChangeDelaySeconds')
408-
$stateChangeMethods = @('Delete', 'Post', 'Patch', 'Put')
409-
if (($stateChangeDelaySeconds -gt 0) -and ($Method -in $stateChangeMethods))
410-
{
411-
Start-Sleep -Seconds $stateChangeDelaySeconds
412-
}
413-
414-
if ($ExtendedResult)
415-
{
416-
$finalResultEx = @{
417-
'result' = $finalResult
418-
'statusCode' = $result.StatusCode
419-
'requestId' = $result.Headers['X-GitHub-Request-Id']
420-
'nextLink' = $nextLink
421-
'nextPageNumber' = $nextPageNumber
422-
'numPages' = $numPages
423-
'since' = $since
424-
'link' = $result.Headers['Link']
425-
'lastModified' = $result.Headers['Last-Modified']
426-
'ifNoneMatch' = $result.Headers['If-None-Match']
427-
'ifModifiedSince' = $result.Headers['If-Modified-Since']
428-
'eTag' = $result.Headers['ETag']
429-
'rateLimit' = $result.Headers['X-RateLimit-Limit']
430-
'rateLimitRemaining' = $result.Headers['X-RateLimit-Remaining']
431-
'rateLimitReset' = $result.Headers['X-RateLimit-Reset']
432-
}
433-
434-
return ([PSCustomObject] $finalResultEx)
435-
}
436-
else
437-
{
438-
return $finalResult
439-
}
440455
}
441456
catch
442457
{

0 commit comments

Comments
 (0)