search

pnp / pnpframework

PnP Framework is a .NET library targeting Microsoft 365 containing the PnP Provisioning engine and a ton of other useful extensions
https://pnp.github.io/pnpframework/
MIT License
205 stars 143 forks source link

Intermittent "User cannot be found" error when calling ApplyProvisioningTemplate #1009

Closed anthonywhite closed 2 months ago

anthonywhite commented 5 months ago

We have a durable .Net 6.x Azure function that orchestrates site creation and the application of one or more PnP Xml templates to the new site. We are seeing an occasional (1 or 2% of time) User cannot be found Exception when executing the ApplyProvisioningTemplate method. This happens in both test and production tenants. Call stack and trace are below. Anyone else seen this before?

versions

  <ItemGroup>
    <PackageReference Include="Microsoft.ApplicationInsights" Version="2.20.0" />
    <PackageReference Include="Microsoft.Azure.Functions.Extensions" Version="1.1.0" />
    <PackageReference Include="Microsoft.Azure.WebJobs.Extensions.DurableTask" Version="2.10.0" />
    <PackageReference Include="Microsoft.NET.Sdk.Functions" Version="4.2.0" />
    <PackageReference Include="PnP.Core.Auth" Version="1.11.0" />
    <PackageReference Include="PnP.Framework" Version="1.14.0" />
  </ItemGroup>

call stack

Microsoft.SharePoint.Client.ServerException:
   at Microsoft.SharePoint.Client.ClientRequest.ProcessResponseStream (Microsoft.SharePoint.Client.Runtime, Version=16.1.0.0, Culture=neutral, PublicKeyToken=71e9bce111e9429c)
   at Microsoft.SharePoint.Client.ClientRequest.ProcessResponse (Microsoft.SharePoint.Client.Runtime, Version=16.1.0.0, Culture=neutral, PublicKeyToken=71e9bce111e9429c)
   at Microsoft.SharePoint.Client.ClientRequest+<ExecuteQueryToServerAsync>d__53.MoveNext (Microsoft.SharePoint.Client.Runtime, Version=16.1.0.0, Culture=neutral, PublicKeyToken=71e9bce111e9429c)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.SharePoint.Client.ClientRequest+<ExecuteQueryAsync>d__39.MoveNext (Microsoft.SharePoint.Client.Runtime, Version=16.1.0.0, Culture=neutral, PublicKeyToken=71e9bce111e9429c)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.SharePoint.Client.ClientRuntimeContext+<ExecuteQueryAsync>d__57.MoveNext (Microsoft.SharePoint.Client.Runtime, Version=16.1.0.0, Culture=neutral, PublicKeyToken=71e9bce111e9429c)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.SharePoint.Client.ClientContext+<ExecuteQueryAsync>d__23.MoveNext (Microsoft.SharePoint.Client, Version=16.1.0.0, Culture=neutral, PublicKeyToken=71e9bce111e9429c)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.SharePoint.Client.ClientContextExtensions+<ExecuteQueryImplementation>d__6.MoveNext (PnP.Framework, Version=1.14.0.0, Culture=neutral, PublicKeyToken=0d501f89f11b748c)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=6.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)
   at Microsoft.SharePoint.Client.ClientContextExtensions.ExecuteQueryRetry (PnP.Framework, Version=1.14.0.0, Culture=neutral, PublicKeyToken=0d501f89f11b748c)
   at PnP.Framework.Provisioning.ObjectHandlers.ObjectSiteSecurity.ProvisionObjects (PnP.Framework, Version=1.14.0.0, Culture=neutral, PublicKeyToken=0d501f89f11b748c)
   at PnP.Framework.Provisioning.ObjectHandlers.SiteToTemplateConversion.ApplyRemoteTemplate (PnP.Framework, Version=1.14.0.0, Culture=neutral, PublicKeyToken=0d501f89f11b748c)
   at KIPSharePointProvAF.Orchestrations.CreateEngagement+<Apply_Template>d__0.MoveNext (KIPSharePointProvAF, Version=1.1.1.0, Culture=neutral, PublicKeyToken=null: /home/vsts/work/1/s/Activities/CreateEngagementApplyTemplate.cs:53)

app insights trace

image

anthonywhite commented 5 months ago

Possibly related to https://github.com/pnp/powershell/discussions/2301 ...

Though I am not deleting and re-creating sites!

anthonywhite commented 4 months ago

Once this has happened on a site, it appears that the template can never be applied after that - fails again and again - as if some corruption has occurred in the site

anthonywhite commented 4 months ago

Have tried an Invoke-PnPSiteTemplate rather than running inside our function. Same error message. Below is the Trace Log - seems to happen right at the top when trying to apply the Security element...

pwsh Information: 0 : 2024-05-07 13:12:17.4856  [Provisioning]  [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:17.4861  [Provisioning]  [19]    [Information]   ProgressDelegate registered 0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:17.4864  [Provisioning]  [19]    [Information]   MessagesDelegate registered 1ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.6102  [Extensibility Providers]   [19]    [Debug] Code execution scope started    7ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.6114  [Extensibility Providers]   [19]    [Debug] Code execution scope ended  8ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.6676  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.6680  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope ended  0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.6710  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.6711  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope ended  0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.6727  [Regional Settings] [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.7419  [Regional Settings] [19]    [Debug] Code execution scope ended  69ms    11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.7423  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.7424  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope ended  0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.7440  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.7441  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope ended  0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:20.7562  [Site Security] [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Error: 0 : 2024-05-07 13:12:22.1163    [PnP.Framework] [0] [Error] ExecuteQuery threw following exception: Microsoft.SharePoint.Client.ServerException: User cannot be found.
   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: -2147024809
ServerErrorTypeName: System.ArgumentException
ServerErrorTraceCorrelationId: 4f5226a1-4008-8000-b6c7-68d740d98dc7
ServerErrorValue: 
ServerErrorDetails: 
.   0ms 
pwsh Information: 0 : 2024-05-07 13:12:22.1166  [Site Security] [19]    [Debug] Code execution scope ended  1360ms  11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:22.1167  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope started    0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:22.1168  [ProvisioningTemplate WebHook Call] [19]    [Debug] Code execution scope ended  0ms 11d605ce-1845-469a-b335-8a2c96ee23cf
pwsh Information: 0 : 2024-05-07 13:12:22.1168  [Provisioning]  [19]    [Debug] Code execution scope ended  4631ms  11d605ce-1845-469a-b335-8a2c96ee23cf
anthonywhite commented 2 months ago

After some intensive trial and error tracing/debugging on this issue, found that the combination of:

will occasionally fail due to the Site Owners group being asynchronously created by a separate process from creation, and sometimes taking longer than usual, hence not being resolvable at the moment the template adds a group

remedy seems to be to delay between site create and template apply, or custom code to check for Owners group visibility before proceeding to template.

Recording this in case of interest to others.