TermGroup and TermSet Provisioning Error - The HTTP service located at .../MetadataWebService.svc is not available

nikolayyordanov commented 6 years ago

Environment

[x] Office 365 / SharePoint Online [ ] SharePoint 2016 [ ] SharePoint 2013

Expected or Desired Behavior

Provision all the terms defined in the TermGroup. May be some error handling and retrying could me done

Observed Behavior

When I try to provision around 10 terms within a termset I get error that the service is not available. It could happen to provision 5 of the 10 or 8 of them or all of the 10 terms.

SchauDK commented 6 years ago

Recently we also started having issues with Term operations.

The request channel timed out attempting to send after 00:00:30. Increase the timeout value passed to the call to Request or increase the SendTimeout value on the Binding. The time allotted to this operation may have been a portion of a longer timeout.

As this is against SharePoint Online, there's no way to change the request timeout.

mpowney commented 5 years ago

I've experienced the same errors on-and-off for the past year or so of using PnP templates against different O365 tenants. Including today, examples below:

MetadataWebService not available:

PS C:\Users\Mark Powney\Documents\Clients\xxx> Apply-PnPProvisioningTemplate -Path "$pwd\Projectsite-template-withapproval.xml"
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:09:21.0931    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:09:21.0940    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:09:21.2220    [Provisioning]  [17]    [Debug] Code execution scope started    0ms 26b48f4e-745b-4036-9a52-8caa5b76ed56
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:09:21.2241    [Provisioning]  [17]    [Information]   ProgressDelegate registered 1ms 26b48f4e-745b-4036-9a52-8caa5b76ed56
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:09:21.2250    [Provisioning]  [17]    [Information]   MessagesDelegate registered 3ms 26b48f4e-745b-4036-9a52-8caa5b76ed56
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:10:28.0975    [Provisioning]  [17]    [Debug] Code execution scope ended  66875ms 26b48f4e-745b-4036-9a52-8caa5b76ed56
Apply-PnPProvisioningTemplate : There was no endpoint listening at http://usr17518-393:32843/0b518ed85e5f41e6b05fb9be3eba7eb0/MetadataWebService.svc that could accept the message. This is often caused by an incorrect address or SOAP 
action. See InnerException, if present, for more details.

Error when commencing the field provisioning stage:

PS C:\Users\Mark Powney\Documents\Clients\xxx> Apply-PnPProvisioningTemplate -Path "$pwd\Projectsite-template-withapproval.xml"
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:13:04.3411    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:13:04.3471    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:13:04.5001    [Provisioning]  [17]    [Debug] Code execution scope started    0ms da46a2bd-98e8-4d83-b17a-33621e4a34a3
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:13:04.5011    [Provisioning]  [17]    [Information]   ProgressDelegate registered 1ms da46a2bd-98e8-4d83-b17a-33621e4a34a3
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:13:04.5031    [Provisioning]  [17]    [Information]   MessagesDelegate registered 2ms da46a2bd-98e8-4d83-b17a-33621e4a34a3
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:25.2171    [Extensibility Providers]   [17]    [Debug] Code execution scope started    0ms da46a2bd-98e8-4d83-b17a-33621e4a34a3
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:25.2181    [Extensibility Providers]   [17]    [Debug] Code execution scope ended  1ms da46a2bd-98e8-4d83-b17a-33621e4a34a3
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:25.3371    [Fields]    [17]    [Debug] Code execution scope started    0ms da46a2bd-98e8-4d83-b17a-33621e4a34a3
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:38.3695    [Fields]    [17]    [Debug] Code execution scope ended  13032ms da46a2bd-98e8-4d83-b17a-33621e4a34a3
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:38.3705    [Provisioning]  [17]    [Debug] Code execution scope ended  213870ms    da46a2bd-98e8-4d83-b17a-33621e4a34a3
Apply-PnPProvisioningTemplate : Object reference not set to an instance of an object on server. The object is associated with method GetDefaultSiteCollectionTermStore.

Error before the field provisioning stage:

PS C:\Users\Mark Powney\Documents\Clients\xxx> Apply-PnPProvisioningTemplate -Path "$pwd\Projectsite-template-withapproval.xml"
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:10:38.7941    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:10:38.7971    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:10:38.9477    [Provisioning]  [17]    [Debug] Code execution scope started    0ms ddd8ca74-ce7d-4ebe-9036-5cb25c1abc3b
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:10:38.9517    [Provisioning]  [17]    [Information]   ProgressDelegate registered 3ms ddd8ca74-ce7d-4ebe-9036-5cb25c1abc3b
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:10:38.9547    [Provisioning]  [17]    [Information]   MessagesDelegate registered 6ms ddd8ca74-ce7d-4ebe-9036-5cb25c1abc3b
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:12:57.3761    [Provisioning]  [17]    [Debug] Code execution scope ended  138427ms    ddd8ca74-ce7d-4ebe-9036-5cb25c1abc3b
Apply-PnPProvisioningTemplate : The operation has timed out.

and finally, The field was found invalid occur randomly on different field GUIDs when executing the same template repeatedly - the field GUID it fails at is always a managed metadata field:

PS C:\Users\Mark Powney\Documents\Clients\xxx> Apply-PnPProvisioningTemplate -Path "$pwd\Projectsite-template-withapproval.xml"
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:55.6647    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:55.6697    [OfficeDevPnP.Core] [0] [Information]   File Projectsite-template-withapproval.xml retrieved from folder    0ms 
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:55.8187    [Provisioning]  [17]    [Debug] Code execution scope started    0ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:55.8297    [Provisioning]  [17]    [Information]   ProgressDelegate registered 11ms    603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:16:55.8317    [Provisioning]  [17]    [Information]   MessagesDelegate registered 13ms    603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:21.4641    [Extensibility Providers]   [17]    [Debug] Code execution scope started    0ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:21.4671    [Extensibility Providers]   [17]    [Debug] Code execution scope ended  2ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:21.4731    [Fields]    [17]    [Debug] Code execution scope started    0ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:24.4721    [Fields]    [17]    [Debug] Adding field {5df6f97c-0c95-47b4-bd4a-1f7b49641e84} to site 2999ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:25.1951    [Fields]    [17]    [Debug] Adding field {f02d23fc-744c-44aa-832c-3ed452fe516c} to site 3721ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:25.5444    [Fields]    [17]    [Debug] Adding field {b72e581b-11be-430a-bbfa-424efde4cf9a} to site 4071ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:28.0430    [Fields]    [17]    [Debug] Adding field {27358bbe-12b8-48ca-ae16-73272faae16a} to site 6570ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:28.3429    [Fields]    [17]    [Debug] Adding field {ef38d5b8-08e7-4db5-bfbd-19e070d7fada} to site 6870ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:29.9162    [Fields]    [17]    [Debug] Adding field {18b41488-ca6a-4d58-99d9-5aecda456e17} to site 8443ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:30.5091    [Fields]    [17]    [Debug] Adding field {1b9da628-3064-4db8-8252-e1cf8ca64fbe} to site 9035ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:30.9825    [Fields]    [17]    [Debug] Adding field {a9011323-cc41-4295-be61-65add9773d02} to site 9509ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:31.4304    [Fields]    [17]    [Debug] Adding field {c119ee7c-62d2-40e2-9628-beb2d9cdb344} to site 9957ms  603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:31.7245    [Fields]    [17]    [Debug] Adding field {4ac51f13-0721-4cea-94a5-6e11d5346985} to site 10251ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:32.1825    [Fields]    [17]    [Debug] Adding field {49304550-8153-4e77-9cb8-2369d8daa4c7} to site 10710ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:32.4697    [Fields]    [17]    [Debug] Adding field {04664301-eb7d-4a07-ac60-00fbe42a4bfb} to site 10997ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:32.7417    [Fields]    [17]    [Debug] Adding field {1cd44f0a-e65b-4f2d-b96a-a0922eafae6d} to site 11268ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:33.2077    [Fields]    [17]    [Debug] Adding field {2ac9160c-cdd0-4b71-85cd-52d38379572f} to site 11734ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:33.6756    [Fields]    [17]    [Debug] Adding field {b62abd0d-124a-4b5c-81a6-2072dce76823} to site 12202ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:33.9516    [Fields]    [17]    [Debug] Adding field {a14a720e-e30e-49a7-83ac-5ea4371a88b3} to site 12479ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:34.5607    [Fields]    [17]    [Debug] Updating field {36193413-DD5C-4096-8C1E-1B40098B9BA3} in site   13088ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:19:34.8197    [Fields]    [17]    [Debug] Adding field {e2073114-160f-4087-95c4-4c4543ceb832} to site 13346ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Error: 0 : 2018-10-26 11:20:16.2627  [Fields]    [17]    [Error] The field was found invalid:    54789ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Error: 0 : 2018-10-26 11:20:16.2647  [Fields]    [17]    [Error] Adding field {e2073114-160f-4087-95c4-4c4543ceb832} failed: The field was found invalid:  :    at OfficeDevPnP.Core.Framework.Provisioning.ObjectHandlers.ObjectFi
eld.CreateField(Web web, XElement templateFieldElement, PnPMonitoredScope scope, TokenParser parser, String originalFieldXml)
   at OfficeDevPnP.Core.Framework.Provisioning.ObjectHandlers.ObjectField.ProvisionObjects(Web web, ProvisioningTemplate template, TokenParser parser, ProvisioningTemplateApplyingInformation applyingInformation) 54791ms 603ad603-d32c-425d-
ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:20:16.2667    [Fields]    [17]    [Debug] Code execution scope ended  54793ms 603ad603-d32c-425d-ac05-2b1ac9029667
PowerShell_ISE.exe Information: 0 : 2018-10-26 11:20:16.2677    [Provisioning]  [17]    [Debug] Code execution scope ended  200448ms    603ad603-d32c-425d-ac05-2b1ac9029667
Apply-PnPProvisioningTemplate : The field was found invalid:

advdberg commented 5 years ago

We now (since today) intermittantly get lots of issues with applying our PnP templates with the following errors:

Object reference not set to an instance of an object on server. The object is associated with method GetDefaultKeywordsTermStore.
The operation has timed out.

It usually fails with this error, but sometimes applying the template succeeds.

Seems like there's something broken on MS side?

@VesaJuvonen @erwinvanhunen any idea on this?

pnp / PnP-Sites-Core