Skip to content

Commit 3e845ca

Browse files
JohnDupreyJohnDuprey
committed
Add detailed HTTP request timing telemetry
Introduces per-request timing using Stopwatch for key steps in New-CippCoreRequest, including access checks, tenant/group resolution, and endpoint invocation. Timings are logged in a structured format for improved observability and performance diagnostics.
1 parent cc3f2ab commit 3e845ca

File tree

1 file changed

+59
-5
lines changed

1 file changed

+59
-5
lines changed

‎Modules/CIPPCore/Public/Entrypoints/HTTP Functions/New-CippCoreRequest.ps1‎

Lines changed: 59 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,10 @@ function New-CippCoreRequest {
1212
[CmdletBinding(SupportsShouldProcess = $true)]
1313
param($Request, $TriggerMetadata)
1414

15+
# Initialize per-request timing
16+
$HttpTimings = @{}
17+
$HttpTotalStopwatch = [System.Diagnostics.Stopwatch]::StartNew()
18+
1519
# Initialize AsyncLocal storage for thread-safe per-invocation context
1620
if (-not $script:CippInvocationIdStorage) {
1721
$script:CippInvocationIdStorage = [System.Threading.AsyncLocal[string]]::new()
@@ -25,7 +29,7 @@ function New-CippCoreRequest {
2529
if (-not $script:CippUserRolesStorage) {
2630
$script:CippUserRolesStorage = [System.Threading.AsyncLocal[hashtable]]::new()
2731
}
28-
32+
2933
# Initialize user roles cache for this request
3034
if (-not $script:CippUserRolesStorage.Value) {
3135
$script:CippUserRolesStorage.Value = @{}
@@ -65,20 +69,39 @@ function New-CippCoreRequest {
6569

6670
if ((Get-Command -Name $FunctionName -ErrorAction SilentlyContinue) -or $FunctionName -eq 'Invoke-Me') {
6771
try {
72+
$swAccess = [System.Diagnostics.Stopwatch]::StartNew()
6873
$Access = Test-CIPPAccess -Request $Request
74+
$swAccess.Stop()
75+
$HttpTimings['AccessCheck'] = $swAccess.Elapsed.TotalMilliseconds
6976
if ($FunctionName -eq 'Invoke-Me') {
77+
$HttpTotalStopwatch.Stop()
78+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
79+
$HttpTimingsRounded = [ordered]@{}
80+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
81+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
7082
return $Access
7183
}
7284
} catch {
7385
Write-Information "Access denied for $FunctionName : $($_.Exception.Message)"
86+
$HttpTotalStopwatch.Stop()
87+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
88+
$HttpTimingsRounded = [ordered]@{}
89+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
90+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
7491
return ([HttpResponseContext]@{
7592
StatusCode = [HttpStatusCode]::Forbidden
7693
Body = $_.Exception.Message
7794
})
7895
}
79-
96+
$swTenants = [System.Diagnostics.Stopwatch]::StartNew()
8097
$AllowedTenants = Test-CippAccess -Request $Request -TenantList
98+
$swTenants.Stop()
99+
$HttpTimings['AllowedTenants'] = $swTenants.Elapsed.TotalMilliseconds
100+
101+
$swGroups = [System.Diagnostics.Stopwatch]::StartNew()
81102
$AllowedGroups = Test-CippAccess -Request $Request -GroupList
103+
$swGroups.Stop()
104+
$HttpTimings['AllowedGroups'] = $swGroups.Elapsed.TotalMilliseconds
82105

83106
if ($AllowedTenants -notcontains 'AllTenants') {
84107
Write-Warning 'Limiting tenant access'
@@ -114,23 +137,39 @@ function New-CippCoreRequest {
114137
}
115138

116139
# Wrap the API call execution with telemetry
117-
$Response = Measure-CippTask -TaskName $Request.Params.CIPPEndpoint -Metadata $metadata -Script {
118-
& $FunctionName @HttpTrigger
119-
}
140+
$swInvoke = [System.Diagnostics.Stopwatch]::StartNew()
141+
$Response = Measure-CippTask -TaskName $Request.Params.CIPPEndpoint -Metadata $metadata -Script { & $FunctionName @HttpTrigger }
142+
$swInvoke.Stop()
143+
$HttpTimings['InvokeEndpoint'] = $swInvoke.Elapsed.TotalMilliseconds
120144

121145
# Filter to only return HttpResponseContext objects
122146
$HttpResponse = $Response | Where-Object { $_.PSObject.TypeNames -eq 'Microsoft.Azure.Functions.PowerShellWorker.HttpResponseContext' }
123147
if ($HttpResponse) {
124148
# Return the first valid HttpResponseContext found
149+
$HttpTotalStopwatch.Stop()
150+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
151+
$HttpTimingsRounded = [ordered]@{}
152+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
153+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
125154
return ([HttpResponseContext]($HttpResponse | Select-Object -First 1))
126155
} else {
127156
# If no valid response context found, create a default success response
128157
if ($Response.PSObject.Properties.Name -contains 'StatusCode' -and $Response.PSObject.Properties.Name -contains 'Body') {
158+
$HttpTotalStopwatch.Stop()
159+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
160+
$HttpTimingsRounded = [ordered]@{}
161+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
162+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
129163
return ([HttpResponseContext]@{
130164
StatusCode = $Response.StatusCode
131165
Body = $Response.Body
132166
})
133167
} else {
168+
$HttpTotalStopwatch.Stop()
169+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
170+
$HttpTimingsRounded = [ordered]@{}
171+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
172+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
134173
return ([HttpResponseContext]@{
135174
StatusCode = [HttpStatusCode]::OK
136175
Body = $Response
@@ -140,18 +179,33 @@ function New-CippCoreRequest {
140179
}
141180
} catch {
142181
Write-Warning "Exception occurred on HTTP trigger ($FunctionName): $($_.Exception.Message)"
182+
$HttpTotalStopwatch.Stop()
183+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
184+
$HttpTimingsRounded = [ordered]@{}
185+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
186+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
143187
return ([HttpResponseContext]@{
144188
StatusCode = [HttpStatusCode]::InternalServerError
145189
Body = $_.Exception.Message
146190
})
147191
}
148192
} else {
193+
$HttpTotalStopwatch.Stop()
194+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
195+
$HttpTimingsRounded = [ordered]@{}
196+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
197+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
149198
return ([HttpResponseContext]@{
150199
StatusCode = [HttpStatusCode]::NotFound
151200
Body = 'Endpoint not found'
152201
})
153202
}
154203
} else {
204+
$HttpTotalStopwatch.Stop()
205+
$HttpTimings['Total'] = $HttpTotalStopwatch.Elapsed.TotalMilliseconds
206+
$HttpTimingsRounded = [ordered]@{}
207+
foreach ($Key in ($HttpTimings.Keys | Sort-Object)) { $HttpTimingsRounded[$Key] = [math]::Round($HttpTimings[$Key], 2) }
208+
Write-Information "#### HTTP Request Timings #### $($HttpTimingsRounded | ConvertTo-Json -Compress)"
155209
return ([HttpResponseContext]@{
156210
StatusCode = [HttpStatusCode]::PreconditionFailed
157211
Body = 'Request not processed'

0 commit comments

Comments
 (0)