[BUG] New-PnPsite delay in PnP.PowerShell 2.5.0

wfi-jonas commented 4 months ago

Reporting an Issue or Missing Feature

I have a provisioning script for sites that uses new-PnPsite in an Azure Function App. When I upgraded my script to use 2.5.0 instead of 2.3.0, the function times out. When I rollback it works perfectly fine and create the site within seconds.

In order to test more I created a simple measure script with only the command new-pnpsite that I ran locally and in the Azure Function App to measure the delay, these are the results (3 tests for each version):

Locally 2.3.0 : 4s37 4s03 4s36 2.5.0 : 4s49 3s89 3s09

Azure function app 2.3.0 : 2s03 5s26 6s65 2.5.0 : timeout (2m40s) timeout (2m40s) timeout (2m40s)

Expected behavior

The site gets created in 2-6 seconds.

Actual behavior

timeout of the function after 2minutes 40 seconds.

Steps to reproduce behavior

Azure function app relevant details:

App service plan on Linux (B3) > cpu 10%, mem 70% avg during tests, so the App service never had resource issues during tests)
Azure Function v4
Azure Function with Private Endpoint
PowerShell 7.4

The script I used to test:

param($Request, $TriggerMetadata) import-module pnp.powershell -RequiredVersion "2.5.0" $c = connect-pnponline -url "https://tenantname-admin.sharepoint.com" -ManagedIdentity -returnconnection try{ $title ="Engine Test 27" $url = "https://tenant name.sharepoint.com/sites/$($title -replace ' ','')" $owner = "my email" $sitedesign = "any design id, or remove it as it doesn't affect the delay" $lcid = 1043 $measure = measure-command { $request = new-pnpsite -connection $c -title $title -sitedesignid $sitedesign -Lcid $lcid -owner $owner -url $url -Type CommunicationSite -wait write-output $request } write-output $measure.TotalSeconds }catch{ write-output $Error[0].Exception -ForegroundColor Red $streamReader = [System.IO.StreamReader]::new($_.Exception.Response.GetResponseStream()) $ErrResp = $streamReader.ReadToEnd() $streamReader.Close() write-output $ErrResp -ForegroundColor Red }

What is the version of the Cmdlet module you are running?

Tested with PnP PowerShell 2.5.0 and 2.3.0.

Which operating system/environment are you running PnP PowerShell on?

[ ] Windows
[ ] Linux
[ ] MacOS
[ ] Azure Cloud Shell
[X] Azure Functions
[ ] Other : please specify

jackpoz commented 4 months ago

Does this happen only when using -ManagedIdentity to connect ? Can you test it with certificate authentication just as a test ?

wfi-jonas commented 4 months ago

I’ve never used anything else when running in functions or runbooks. Locally on my machine with interactive both versions where working fine, provisioning was done in 2-6 seconds.

gautamdsheth commented 3 months ago

@wfi-jonas - can you do a perf on just the connect-pnponline with managed identity and let us know ? We did bump the MSAL to the latest version, so maybe that could be the issue ?

wfi-jonas commented 3 months ago

What do you mean by perf?

gautamdsheth commented 3 months ago

@wfi-jonas - sorry I meant , can you just measure the difference in connect-pnponline between these 2 versions ?

wfi-jonas commented 3 months ago

Sorry but that doesn’t make sense. In my measure script above I don’t take into account the time it takes to connect because I saw there was no delay there. So I only measured what I found was the causing the delay.

Is new-pnpsite perhaps targeting different urls? In the changelog I didn’t see any update for this command, but perhaps some change slipped in between 2.3.0 and 2.5.0. Perhaps some dependency on this command?

wfi-jonas commented 3 months ago

Hm I don’t see anything wrong in this change..

gautamdsheth commented 3 months ago

The only change that we have done is update MSAL.NET that we use for authentication to the latest version . We were using an older version which had security vulnerabilities, so we bumped it to the latest version. No other change was done related to site provisioning.

gautamdsheth commented 3 months ago

@wfi-jonas - can you please try again with tomorrow's or latest nightly builds again ? We made some changes to token fetching and other things, maybe that helps ?

wfi-jonas commented 3 months ago

hello @gautamdsheth , I'm currently not in the office. I'll test this later this week. Thank you for looking into this!

veronicageek commented 2 months ago

@wfi-jonas - Closing this for now. Let us know if you need it reopened after your testing.

wfi-jonas commented 2 months ago

hello, sorry for the late reply as it has been super busy.

I've just tested this with PnP 2.12.0. I'm not getting a timeout but it still takes 1minute 40 seconds on avg to create a site with only the cmdlet new-pnpsite, no other configuration. While locally it takes just a few seconds. Sadly I have this delay also now with Pnp 2.3.0.

This is an issue for me as I'm trying to create a sync process to create & configure sites; I really don't want to revert to a async setup with callback mechanisms. Ideally the site would be created in 4-10seconds max.

Has anymore very tested this in an azure functions with same details?

How does the -wait parameter work? Are you constantly checking if the site has been created or are you waiting for a MSFT callback? I would say this is a MSFT service issue ifnot it would work so much faster locally.

The other extra thing I can think of is our vnet/private endpoint setup around the Azure function and its app service plan. Perhaps there is throttling somewhere.. Depending on how the wait work, perhaps there is a issue here in relation with vnet/pe?

-Wait If specified the cmdlet will wait until the site has been fully created and all site artifacts have been provisioned by SharePoint. Notice that this can take a while.

wfi-jonas commented 2 months ago

I created a azure function with app service plan (B2) without any vnet/pe integration. Using PnP.Powershell 2.12.0 this code takes 71 seconds!

$measure = measure-command { $request = new-pnpsite -connection $c -title $title -Lcid $lcid -owner $owner -url $url -Type CommunicationSite -wait } write-output $measure.TotalSeconds

2024-10-01T07:42:50Z [Information] INFORMATION: PowerShell HTTP trigger function processed a request. 2024-10-01T07:44:03Z [Information] OUTPUT: 71.1120775 2024-10-01T07:44:03Z [Information] Executed 'Functions.HttpTrigger1' (Succeeded, Id=19164b45-06c7-424a-befe-1047f8b06e89, Duration=122379ms)

wfi-jonas commented 2 months ago

using PnP.Powershell 2.3.0 in this function takes 94s to create a site.. :/

Any ideas? @veronicageek can you re-open please?

wfi-jonas commented 2 months ago

azure function in consumption hosting with pnp.powershell 2.12.0: also 70s to create a site. So app service hosting with or without vnet/pe isn't the problem.

gautamdsheth commented 1 month ago

What is it you want us investigate ? We don't have any specific code for Azure functions which should cause slowness.

wfi-jonas commented 1 month ago

@gautamdsheth so I need to escalate this towards MSFT? Any idea which team at MSFT can help? Does new-pnpsite use csom or rest api's?

wfi-jonas commented 3 weeks ago

I've found new information thanks to @algraps

For the local tests with -interactive I added the following to my measure script: Set-PnPTraceLog -On -level Debug -WriteToConsole It shows 2x System.UnauthorizedAccessException, while the website is created. So this output shows tha the -wait param for new-pnpsite does not work (I had SharePoint admin role active).

pwsh Information: 0 : 2024-11-06 12:51:41.3952 [GetAccessTokenAsync] [0] [Debug] Authentication type: AzureADInteractive 0ms pwsh Information: 0 : 2024-11-06 12:51:41.3973 [GetAccessTokenAsync] [0] [Debug] Authentication type: AzureADInteractive 0ms pwsh Information: 0 : 2024-11-06 12:51:41.6339 [GetAccessTokenAsync] [0] [Debug] Authentication type: AzureADInteractive 0ms pwsh Information: 0 : 2024-11-06 12:51:44.5503 [PnP.Framework] [0] [Debug] Cloning context for https://OURTENANT.sharepoint.com/sites/EngineTest126 0ms pwsh Information: 0 : 2024-11-06 12:51:44.5512 [PnP.Framework] [0] [Debug] Checking for different audience https://OURTENANT.sharepoint.com/sites/EngineTest126 0ms pwsh Information: 0 : 2024-11-06 12:51:44.5517 [PnP.Framework] [0] [Debug] Setting up context for different audience AzureADInteractive 0ms pwsh Information: 0 : 2024-11-06 12:51:44.5523 [GetContextAsync] [0] [Debug] Authentication type: AzureADInteractive for scopes https://OURTENANT.sharepoint.com/.default 0ms pwsh Error: 0 : 2024-11-06 12:51:45.0603 [PnP.Framework] [0] [Error] ExecuteQuery threw following exception: Microsoft.SharePoint.Client.ServerUnauthorizedAccessException: Attempted to perform an unauthorized operation. at Microsoft.SharePoint.Client.ClientRequest.ProcessResponseStream(Stream responseStream) at Microsoft.SharePoint.Client.ClientRequest.ProcessResponse() at Microsoft.SharePoint.Client.ClientRequest.ExecuteQueryToServerAsync(ChunkStringBuilder sb) at Microsoft.SharePoint.Client.ClientRequest.ExecuteQueryAsync() at Microsoft.SharePoint.Client.ClientRuntimeContext.ExecuteQueryAsync() at Microsoft.SharePoint.Client.ClientContext.ExecuteQueryAsync() at Microsoft.SharePoint.Client.ClientContextExtensions.ExecuteQueryImplementation(ClientRuntimeContext clientContext, Int32 retryCount, String userAgent) ServerErrorCode: -2147024891 ServerErrorTypeName: System.UnauthorizedAccessException ServerErrorTraceCorrelationId: dd3761a1-a043-a000-5342-c9123948ddd7 ServerErrorValue: ServerErrorDetails: . 0ms pwsh Information: 0 : 2024-11-06 12:51:45.0676 [PnP.Framework] [0] [Debug] Starting to wait for site collection to be created 0ms pwsh Information: 0 : 2024-11-06 12:51:45.0688 [PnP.Framework] [0] [Debug] Elapsed: 00:00.000 | Attempt 1/80 0ms pwsh Error: 0 : 2024-11-06 12:51:45.1526 [PnP.Framework] [0] [Error] ExecuteQuery threw following exception: Microsoft.SharePoint.Client.ServerUnauthorizedAccessException: Attempted to perform an unauthorized operation. at Microsoft.SharePoint.Client.ClientRequest.ProcessResponseStream(Stream responseStream) at Microsoft.SharePoint.Client.ClientRequest.ProcessResponse() at Microsoft.SharePoint.Client.ClientRequest.ExecuteQueryToServerAsync(ChunkStringBuilder sb) at Microsoft.SharePoint.Client.ClientRequest.ExecuteQueryAsync() at Microsoft.SharePoint.Client.ClientRuntimeContext.ExecuteQueryAsync() at Microsoft.SharePoint.Client.ClientContext.ExecuteQueryAsync() at Microsoft.SharePoint.Client.ClientContextExtensions.ExecuteQueryImplementation(ClientRuntimeContext clientContext, Int32 retryCount, String userAgent) ServerErrorCode: -2147024891 ServerErrorTypeName: System.UnauthorizedAccessException ServerErrorTraceCorrelationId: dd3761a1-504a-a000-5342-cca67700b00e ServerErrorValue: ServerErrorDetails:

For using the same new-pnpsite command from an Azure function we found the following:

$measure = measure-command { $request = new-pnpsite -connection $c -title $title -Lcid $lcid -owner $owner -url $url -Type CommunicationSite -wait write-output $request }

this takes 40-90 seconds for it to create the website and print the output.

The following test without the -wait param and using a do until: $measure = measure-command { $request = new-pnpsite -connection $c -title $title -Lcid $lcid -owner $owner -url $url -Type CommunicationSite write-output $request Do { $site = Get-PnPTenantSite -Url $url -ErrorAction SilentlyContinue -connection $c $counter++ Start-sleep -seconds 1 } Until (($counter -eq $max) -or ($site))

}

this takes 4 seconds to create the website and provide the output print.

The Pnp-tracelog from the azure functions shows it tries 2x to get the website and then waits 15 seconds in between. Was this changed? Can we tweak this or perhaps have a parameter to define how many seconds it has to wait in between?

wfi-jonas commented 3 weeks ago

the output from azure function tracelog:

root@bad9c0122f2c:~# cat /home/pnptrace.txt Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:28.1587 [PnP.Framework] [0] [Debug] Starting to wait for site collection to be created 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:28.1721 [PnP.Framework] [0] [Debug] Elapsed: 00:00.000 | Attempt 1/80 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:28.2366 [PnP.Framework] [0] [Debug] Elapsed: 00:00.066 | Attempt 2/80 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:28.2368 [PnP.Framework] [0] [Debug] Elapsed: 00:00.066 | Waiting 15 seconds 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:43.2839 [PnP.Framework] [0] [Debug] Elapsed: 00:15.113 | Attempt 3/80 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:43.2841 [PnP.Framework] [0] [Debug] Elapsed: 00:15.113 | Waiting 15 seconds 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:48.4054 [PnP.Framework] [0] [Debug] Starting to wait for site collection to be created 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:48.4225 [PnP.Framework] [0] [Debug] Elapsed: 00:00.000 | Attempt 1/80 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:48.4792 [PnP.Framework] [0] [Debug] Elapsed: 00:00.056 | Attempt 2/80 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:48.4809 [PnP.Framework] [0] [Debug] Elapsed: 00:00.058 | Waiting 15 seconds 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:58.3310 [PnP.Framework] [0] [Debug] Elapsed: 00:30.160 | Attempt 4/80 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:56:58.3356 [PnP.Framework] [0] [Debug] Elapsed: 00:30.165 | Waiting 15 seconds 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:57:03.5308 [PnP.Framework] [0] [Debug] Elapsed: 00:15.108 | Attempt 3/80 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:57:03.5326 [PnP.Framework] [0] [Debug] Elapsed: 00:15.110 | Waiting 15 seconds 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:57:13.4028 [PnP.Framework] [0] [Debug] Elapsed: 00:45.232 | Finished 0ms Microsoft.Azure.Functions.PowerShellWorker Information: 0 : 2024-11-06 11:57:18.6050 [PnP.Framework] [0] [Debug] Elapsed: 00:30.166 | Finished 0ms root@bad9c0122f2c:~# ^C root@bad9c0122f2c:~#

wfi-jonas commented 3 weeks ago

@gautamdsheth can you please look over our findings? Thank you in advance.

TLDR:

using -wait us bugged in combination with -interactive and SharePoint admin role.
using -wait in Azure function works but show intervals of 15 seconds. Was this changed from 2.3.0 onwards somewhere? Can we make these values tweakable? For example new-pnpsite -url $url -wait -waitinterval 4 -maxwait 40.

rvdwegen commented 3 weeks ago

@wfi-jonas I'm running into similair but worse performance for New-PnPSite but locally in powershell. The site gets created but New-PnPSite simply never continues when used in a loop.

wfi-jonas commented 3 weeks ago

@rvdwegen what authentication method do you use? try activating Set-PnPTraceLog and look for the poller mechanism.

rvdwegen commented 3 weeks ago

@wfi-jonas Delegated auth (over GDAP) through our own app. But that shouldn't be the issue because it does create the site.

wfi-jonas commented 3 weeks ago

you can see above that for me with interactive authentication the behavior is different from using a managed identity. So yes authentication matters. Even f the site is created, check performed when using -wait required different permissions apparently.

You need to specify what authentication parameters you use for new-pnpsite (-interactive or any other), what permissions does the account has). Next the output of set-pnptracelog helps to show if you have the same issue as me.

My issue is descripted just a few comments above in the TLDR.

rvdwegen commented 3 weeks ago

#Connect to PnP Online
Connect-PnPOnline -Url $AdminSiteURL -Interactive -ApplicationId "c1dcebba-920d-4180-bfdc-905e38b0cfdc"

# Import Csv data and test if all expected columns exist
$Sites = Get-CSVdata -CorrectHeaders @('Title', 'Alias', 'Owner', 'Type', 'Hubsite', 'HubsiteAlias')

$baseSharePointUrl = (Get-PnPContext).Url -Replace ("-admin","")

$Sites | ForEach-Object { 
    New-PnPSite -Wait:$false -Type CommunicationSite -Title $_.Title -Url ($baseSharePointUrl + "sites/" + $_.Alias) 
}

Above is an oversimplified version of what we'd like to run. I'd also like to note we tried all types of powershell loops.

The above has been ran with and without -Wait:$false. The account used is GA in the tenant. Set-pnptracelog does not give any output for New-PnPSite. There are no other PnP connections present in the process.

The site is created, but we get zero feedback and the loop just stalls. It never gets past New-PnPSite.

Edit: just because I just tried in app auth context with a cert, same result.

wfi-jonas commented 3 weeks ago

with -wait on $false you will never get feedback I think. You'll just submit the job move to the next line/task. With -wait on $true, the creation should wait until the site is created. I mostly do $site = new-pnpsite and then write-output $site for example.

Also in your example, you might want to check what it does when a site already exists, perhaps you need to handle the error with for example modify the -ErrorAction to SilentlyContinue.

If your loop stalls this might be because you are hitting API throlling limits. Try implementing a counter to see after how many iterations of the loop stalls. Also API throlling limits for user accounts are not really documented as for application throttling, but there are limits you might reach when doing automation stuff. https://learn.microsoft.com/en-us/sharepoint/dev/general-development/how-to-avoid-getting-throttled-or-blocked-in-sharepoint-online#user-throttling

As for Set-pnptracelog, I do get traces as shown above for new-pnpsite. Check the parameters for this cmdlet here: https://pnp.github.io/powershell/cmdlets/Set-PnPTraceLog.html

So far this does not look like the same issue I'm facing here and trying to get solved.

rvdwegen commented 3 weeks ago

No you're not getting it. The loop stalls, period. It never gets past the first time it executes New-PnPSite. I do not get a warning, I do not get any debug info, I do not get an error. I do not pass go. Literally nothing happens in the console as soon as it hits the first New-PnPSite.

I'm using set-PnPTraceLog -On -level Debug -WriteToConsole just like you.

-Wait, Wait:$false and no Wait all make no difference at all.

wfi-jonas commented 3 weeks ago

I'm giving tips on the information you give me.

So the website gets created, but your powershell session keep running and the loop does not go to the second site. If you run new-pnpsite without the loop, do you then get any feedback or log? will the powershell session the finish?

Nevertheless without -wait it should not wait and go to the next line. This is not what I'm experiencing, when I remove -wait my cmdlet will finish. When I add wait, it will also finish in a few seconds because the built-in poller (80 tries with 15s intervals) does not work with SharePoint Admin role active.

rvdwegen commented 3 weeks ago

Sorry, I've just had this same conversation a fair few times the last 5 hours.

If I run new-pnpsite outside of a loop, it works and I get a response in ~2 seconds.

pnp / powershell