Skip to content

Commit 9684634

Browse files
JohnDupreyJohnDuprey
committed
Add detailed profiling to access and user role checks
Introduced per-call profiling using Stopwatch in Test-CIPPAccess and Test-CIPPAccessUserRole functions. Timings for key operations are collected and logged for performance analysis, aiding in identifying bottlenecks during authentication and authorization flows.
1 parent 3e845ca commit 9684634

File tree

2 files changed

+80
-0
lines changed

2 files changed

+80
-0
lines changed

‎Modules/CIPPCore/Public/Authentication/Test-CIPPAccess.ps1‎

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,26 +4,35 @@ function Test-CIPPAccess {
44
[switch]$TenantList,
55
[switch]$GroupList
66
)
7+
# Initialize per-call profiling
8+
$AccessTimings = @{}
9+
$AccessTotalSw = [System.Diagnostics.Stopwatch]::StartNew()
710
if ($Request.Params.CIPPEndpoint -eq 'ExecSAMSetup') { return $true }
811

912
# Get function help
1013
$FunctionName = 'Invoke-{0}' -f $Request.Params.CIPPEndpoint
1114

1215
if ($FunctionName -ne 'Invoke-me') {
16+
$swHelp = [System.Diagnostics.Stopwatch]::StartNew()
1317
try {
1418
$Help = Get-Help $FunctionName -ErrorAction Stop
1519
} catch {
1620
Write-Warning "Function '$FunctionName' not found"
1721
}
22+
$swHelp.Stop()
23+
$AccessTimings['GetHelp'] = $swHelp.Elapsed.TotalMilliseconds
1824
}
1925

2026
# Check help for role
2127
$APIRole = $Help.Role
2228

2329
# Get default roles from config
30+
$swRolesLoad = [System.Diagnostics.Stopwatch]::StartNew()
2431
$CIPPCoreModuleRoot = Get-Module -Name CIPPCore | Select-Object -ExpandProperty ModuleBase
2532
$CIPPRoot = (Get-Item $CIPPCoreModuleRoot).Parent.Parent
2633
$BaseRoles = Get-Content -Path $CIPPRoot\Config\cipp-roles.json | ConvertFrom-Json
34+
$swRolesLoad.Stop()
35+
$AccessTimings['LoadBaseRoles'] = $swRolesLoad.Elapsed.TotalMilliseconds
2736
$DefaultRoles = @('superadmin', 'admin', 'editor', 'readonly', 'anonymous', 'authenticated')
2837

2938
if ($APIRole -eq 'Public') {
@@ -32,6 +41,7 @@ function Test-CIPPAccess {
3241

3342
if ($Request.Headers.'x-ms-client-principal-idp' -eq 'aad' -and $Request.Headers.'x-ms-client-principal-name' -match '^[0-9a-fA-F]{8}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{4}-[0-9a-fA-F]{12}$') {
3443
$Type = 'APIClient'
44+
$swApiClient = [System.Diagnostics.Stopwatch]::StartNew()
3545
# Direct API Access
3646
$ForwardedFor = $Request.Headers.'x-forwarded-for' -split ',' | Select-Object -First 1
3747
$IPRegex = '^(?<IP>(?:\d{1,3}(?:\.\d{1,3}){3}|\[[0-9a-fA-F:]+\]|[0-9a-fA-F:]+))(?::\d+)?$'
@@ -92,14 +102,20 @@ function Test-CIPPAccess {
92102
} | ConvertTo-Json -Depth 5)
93103
})
94104
}
105+
$swApiClient.Stop()
106+
$AccessTimings['ApiClientBranch'] = $swApiClient.Elapsed.TotalMilliseconds
95107

96108
} else {
97109
$Type = 'User'
110+
$swUserBranch = [System.Diagnostics.Stopwatch]::StartNew()
98111
$User = [System.Text.Encoding]::UTF8.GetString([System.Convert]::FromBase64String($Request.Headers.'x-ms-client-principal')) | ConvertFrom-Json
99112

100113
# Check for roles granted via group membership
101114
if (($User.userRoles | Measure-Object).Count -eq 2 -and $User.userRoles -contains 'authenticated' -and $User.userRoles -contains 'anonymous') {
115+
$swResolveUserRoles = [System.Diagnostics.Stopwatch]::StartNew()
102116
$User = Test-CIPPAccessUserRole -User $User
117+
$swResolveUserRoles.Stop()
118+
$AccessTimings['ResolveUserRoles'] = $swResolveUserRoles.Elapsed.TotalMilliseconds
103119
}
104120

105121
#Write-Information ($User | ConvertTo-Json -Depth 5)
@@ -117,7 +133,10 @@ function Test-CIPPAccess {
117133
})
118134
}
119135

136+
$swPermsMe = [System.Diagnostics.Stopwatch]::StartNew()
120137
$Permissions = Get-CippAllowedPermissions -UserRoles $User.userRoles
138+
$swPermsMe.Stop()
139+
$AccessTimings['GetPermissions(me)'] = $swPermsMe.Elapsed.TotalMilliseconds
121140
return ([HttpResponseContext]@{
122141
StatusCode = [HttpStatusCode]::OK
123142
Body = (
@@ -187,8 +206,12 @@ function Test-CIPPAccess {
187206
if (@('admin', 'superadmin') -contains $BaseRole.Name) {
188207
return $true
189208
} else {
209+
$swTenantsLoad = [System.Diagnostics.Stopwatch]::StartNew()
190210
$Tenants = Get-Tenants -IncludeErrors
211+
$swTenantsLoad.Stop()
212+
$AccessTimings['LoadTenants'] = $swTenantsLoad.Elapsed.TotalMilliseconds
191213
$PermissionsFound = $false
214+
$swRolePerms = [System.Diagnostics.Stopwatch]::StartNew()
192215
$PermissionSet = foreach ($CustomRole in $CustomRoles) {
193216
try {
194217
Get-CIPPRolePermissions -Role $CustomRole
@@ -198,9 +221,12 @@ function Test-CIPPAccess {
198221
continue
199222
}
200223
}
224+
$swRolePerms.Stop()
225+
$AccessTimings['GetRolePermissions'] = $swRolePerms.Elapsed.TotalMilliseconds
201226

202227
if ($PermissionsFound) {
203228
if ($TenantList.IsPresent) {
229+
$swTenantList = [System.Diagnostics.Stopwatch]::StartNew()
204230
$LimitedTenantList = foreach ($Permission in $PermissionSet) {
205231
if ((($Permission.AllowedTenants | Measure-Object).Count -eq 0 -or $Permission.AllowedTenants -contains 'AllTenants') -and (($Permission.BlockedTenants | Measure-Object).Count -eq 0)) {
206232
@('AllTenants')
@@ -240,8 +266,11 @@ function Test-CIPPAccess {
240266
$ExpandedAllowedTenants | Where-Object { $ExpandedBlockedTenants -notcontains $_ }
241267
}
242268
}
269+
$swTenantList.Stop()
270+
$AccessTimings['BuildTenantList'] = $swTenantList.Elapsed.TotalMilliseconds
243271
return @($LimitedTenantList | Sort-Object -Unique)
244272
} elseif ($GroupList.IsPresent) {
273+
$swGroupList = [System.Diagnostics.Stopwatch]::StartNew()
245274
Write-Information "Getting allowed groups for roles: $($CustomRoles -join ', ')"
246275
$LimitedGroupList = foreach ($Permission in $PermissionSet) {
247276
if ((($Permission.AllowedTenants | Measure-Object).Count -eq 0 -or $Permission.AllowedTenants -contains 'AllTenants') -and (($Permission.BlockedTenants | Measure-Object).Count -eq 0)) {
@@ -254,11 +283,14 @@ function Test-CIPPAccess {
254283
}
255284
}
256285
}
286+
$swGroupList.Stop()
287+
$AccessTimings['BuildGroupList'] = $swGroupList.Elapsed.TotalMilliseconds
257288
return @($LimitedGroupList | Sort-Object -Unique)
258289
}
259290

260291
$TenantAllowed = $false
261292
$APIAllowed = $false
293+
$swPermissionEval = [System.Diagnostics.Stopwatch]::StartNew()
262294
foreach ($Role in $PermissionSet) {
263295
foreach ($Perm in $Role.Permissions) {
264296
if ($Perm -match $APIRole) {
@@ -329,6 +361,8 @@ function Test-CIPPAccess {
329361
}
330362
}
331363
}
364+
$swPermissionEval.Stop()
365+
$AccessTimings['EvaluatePermissions'] = $swPermissionEval.Elapsed.TotalMilliseconds
332366

333367
if (!$APIAllowed) {
334368
throw "Access to this CIPP API endpoint is not allowed, you do not have the required permission: $APIRole"
@@ -392,10 +426,22 @@ function Test-CIPPAccess {
392426
}
393427
return $true
394428
}
429+
$swUserBranch.Stop()
430+
$AccessTimings['UserBranch'] = $swUserBranch.Elapsed.TotalMilliseconds
395431
}
396432

397433
if ($TenantList.IsPresent) {
434+
$AccessTotalSw.Stop()
435+
$AccessTimings['Total'] = $AccessTotalSw.Elapsed.TotalMilliseconds
436+
$AccessTimingsRounded = [ordered]@{}
437+
foreach ($Key in ($AccessTimings.Keys | Sort-Object)) { $AccessTimingsRounded[$Key] = [math]::Round($AccessTimings[$Key], 2) }
438+
Write-Information "#### Access Timings #### $($AccessTimingsRounded | ConvertTo-Json -Compress)"
398439
return @('AllTenants')
399440
}
441+
$AccessTotalSw.Stop()
442+
$AccessTimings['Total'] = $AccessTotalSw.Elapsed.TotalMilliseconds
443+
$AccessTimingsRounded = [ordered]@{}
444+
foreach ($Key in ($AccessTimings.Keys | Sort-Object)) { $AccessTimingsRounded[$Key] = [math]::Round($AccessTimings[$Key], 2) }
445+
Write-Information "#### Access Timings #### $($AccessTimingsRounded | ConvertTo-Json -Compress)"
400446
return $true
401447
}

‎Modules/CIPPCore/Public/Authentication/Test-CIPPAccessUserRole.ps1‎

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,9 @@ function Test-CIPPAccessUserRole {
1919
param(
2020
$User
2121
)
22+
# Initialize per-call profiling
23+
$UserRoleTimings = @{}
24+
$UserRoleTotalSw = [System.Diagnostics.Stopwatch]::StartNew()
2225
$Roles = @()
2326

2427
# Check AsyncLocal cache first (per-request cache)
@@ -27,9 +30,12 @@ function Test-CIPPAccessUserRole {
2730
} else {
2831
# Check table storage cache (persistent cache)
2932
try {
33+
$swTableLookup = [System.Diagnostics.Stopwatch]::StartNew()
3034
$Table = Get-CippTable -TableName cacheAccessUserRoles
3135
$Filter = "PartitionKey eq 'AccessUser' and RowKey eq '$($User.userDetails)' and Timestamp ge datetime'$((Get-Date).AddMinutes(-15).ToUniversalTime().ToString('yyyy-MM-ddTHH:mm:ss.fffZ'))'"
3236
$UserRole = Get-CIPPAzDataTableEntity @Table -Filter $Filter
37+
$swTableLookup.Stop()
38+
$UserRoleTimings['TableLookup'] = $swTableLookup.Elapsed.TotalMilliseconds
3339
} catch {
3440
Write-Information "Could not access cached user roles table. $($_.Exception.Message)"
3541
$UserRole = $null
@@ -44,29 +50,47 @@ function Test-CIPPAccessUserRole {
4450
}
4551
} else {
4652
try {
53+
$swGraphMemberships = [System.Diagnostics.Stopwatch]::StartNew()
4754
$uri = "https://graph.microsoft.com/beta/users/$($User.userDetails)/transitiveMemberOf"
4855
$Memberships = New-GraphGetRequest -uri $uri -NoAuthCheck $true -AsApp $true | Where-Object { $_.'@odata.type' -eq '#microsoft.graph.group' }
56+
$swGraphMemberships.Stop()
57+
$UserRoleTimings['GraphMemberships'] = $swGraphMemberships.Elapsed.TotalMilliseconds
4958
if ($Memberships) {
5059
Write-Information "Found group memberships for $($User.userDetails)"
5160
} else {
5261
Write-Information "No group memberships found for $($User.userDetails)"
5362
}
5463
} catch {
5564
Write-Information "Could not get user roles for $($User.userDetails). $($_.Exception.Message)"
65+
$UserRoleTotalSw.Stop()
66+
$UserRoleTimings['Total'] = $UserRoleTotalSw.Elapsed.TotalMilliseconds
67+
$timingsRounded = [ordered]@{}
68+
foreach ($Key in ($UserRoleTimings.Keys | Sort-Object)) { $timingsRounded[$Key] = [math]::Round($UserRoleTimings[$Key], 2) }
69+
Write-Information "#### UserRole Timings #### $($timingsRounded | ConvertTo-Json -Compress)"
5670
return $User
5771
}
5872

73+
$swAccessGroups = [System.Diagnostics.Stopwatch]::StartNew()
5974
$AccessGroupsTable = Get-CippTable -TableName AccessRoleGroups
6075
$AccessGroups = Get-CIPPAzDataTableEntity @AccessGroupsTable -Filter "PartitionKey eq 'AccessRoleGroups'"
76+
$swAccessGroups.Stop()
77+
$UserRoleTimings['AccessGroupsFetch'] = $swAccessGroups.Elapsed.TotalMilliseconds
78+
79+
$swCustomRoles = [System.Diagnostics.Stopwatch]::StartNew()
6180
$CustomRolesTable = Get-CippTable -TableName CustomRoles
6281
$CustomRoles = Get-CIPPAzDataTableEntity @CustomRolesTable -Filter "PartitionKey eq 'CustomRoles'"
82+
$swCustomRoles.Stop()
83+
$UserRoleTimings['CustomRolesFetch'] = $swCustomRoles.Elapsed.TotalMilliseconds
6384
$BaseRoles = @('superadmin', 'admin', 'editor', 'readonly')
6485

86+
$swDeriveRoles = [System.Diagnostics.Stopwatch]::StartNew()
6587
$Roles = foreach ($AccessGroup in $AccessGroups) {
6688
if ($Memberships.id -contains $AccessGroup.GroupId -and ($CustomRoles.RowKey -contains $AccessGroup.RowKey -or $BaseRoles -contains $AccessGroup.RowKey)) {
6789
$AccessGroup.RowKey
6890
}
6991
}
92+
$swDeriveRoles.Stop()
93+
$UserRoleTimings['DeriveRoles'] = $swDeriveRoles.Elapsed.TotalMilliseconds
7094

7195
$Roles = @($Roles) + @($User.userRoles)
7296

@@ -76,12 +100,15 @@ function Test-CIPPAccessUserRole {
76100

77101
if (($Roles | Measure-Object).Count -gt 2) {
78102
try {
103+
$swCacheWrite = [System.Diagnostics.Stopwatch]::StartNew()
79104
$UserRole = [PSCustomObject]@{
80105
PartitionKey = 'AccessUser'
81106
RowKey = [string]$User.userDetails
82107
Role = [string](ConvertTo-Json -Compress -InputObject $Roles)
83108
}
84109
Add-CIPPAzDataTableEntity @Table -Entity $UserRole -Force
110+
$swCacheWrite.Stop()
111+
$UserRoleTimings['TableWrite'] = $swCacheWrite.Elapsed.TotalMilliseconds
85112
} catch {
86113
Write-Information "Could not cache user roles for $($User.userDetails). $($_.Exception.Message)"
87114
}
@@ -95,5 +122,12 @@ function Test-CIPPAccessUserRole {
95122
}
96123
$User.userRoles = $Roles
97124

125+
# Log timings summary
126+
$UserRoleTotalSw.Stop()
127+
$UserRoleTimings['Total'] = $UserRoleTotalSw.Elapsed.TotalMilliseconds
128+
$timingsRounded = [ordered]@{}
129+
foreach ($Key in ($UserRoleTimings.Keys | Sort-Object)) { $timingsRounded[$Key] = [math]::Round($UserRoleTimings[$Key], 2) }
130+
Write-Information "#### UserRole Timings #### $($timingsRounded | ConvertTo-Json -Compress)"
131+
98132
return $User
99133
}

0 commit comments

Comments
 (0)