David Kitchen

Project Server splits project data across two areas: Project Server holds the plan data (Tasks, Milestones) & resourcing data (Resources, Timesheets), and then SharePoint (WSS or MOSS) holds the Risks, Issues, Documents and other custom data.

When a project is initially published in Project Server, PWA (Project Web Access) will attempt to provision a new SharePoint subweb. This means Project Server creates a Project Workspace in SharePoint.

The problem I’m witnessing? That even manually creating the workspace results in a single dialog box in which the only text is “Error”.

So how to get to the bottom of this? Let’s work through how I found the bug.

First up was recognising the symptoms I was witnessing and collating key facts:

• The template used to provision the Project Workspace is a custom template.
• The custom template has been saved as a *.stp (Site Template) file.
• The *.stp file is over 4MB in size.
• *.stp files are really *.cab files.
• Looking inside the *.stp file I could see that there was a 30MB manifest.xml file that defined the SharePoint site in CAML (Collaborative Application Markup Language)
• A 30MB XML file can easily take a considerable amount of RAM, using Process Explorer I estimated that this particular file took 2GB of RAM to work with.
• When Project Server was instructed to provision a Project Workspace it took approx 100 seconds to produce the generic error message, regardless of the environment or capability of the servers I tested on.
• When STSADM.exe was used to manually provision a subweb I saw that it would always complete successfully, but it would take anywhere from 180 to 240 seconds depending on environment and server load.
• Because Project Server is a SharePoint application, the SharePoint logs show information for both products.
• The log files suggest a timeout.

So that much is known… the provisioning is timed out, even though SharePoint on it’s own would successfully provision a subweb if given the chance to.

Next up… how to step through what Project Server is doing so that we can find where the timeout might be. To do this I would need to be able to see what the Project Server admin web pages were doing, and specifically what the http://www.example.com/pwa/_layouts/PWA/Admin/ManageWSS.aspx page does when you click on the “Create Site” button. For this, I would need the help of DebugBar.

What happens when you click on “Create Site” is that an AJAX call is made:
POST /pwa/_layouts/pwa/Admin/ManageWSS.aspx HTTP/1.1
Accept: */*
Accept-Language: en-gb
pj_server_callback: 1
Referer: http://ukp12/pwa/_layouts/pwa/Admin/ManageWSS.aspx
Content-Type:application/x-www-form-urlencoded
UA-CPU: x86
Accept-Encoding: gzip, deflate
User-Agent: Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.2; .NET CLR 1.1.4322; .NET CLR 2.0.50727; .NET CLR 3.0.04506.30; InfoPath.2; .NET CLR 3.0.04506.648; .NET CLR 3.5.21022)
Host: ukp12
Content-Length: 690
Connection: Keep-Alive
Cache-Control: no-cache
Authorization: Negotiate TlRMTVNTUAADAAAAAAAAAEgAAAAAAAAASAAAAAAAAABIAAAAA AAAAEgAAAAAAAAASAAAAAAAAABIAAAABcKIogUCzg4AAAAP

__REQUESTDIGEST=0xB55C7C12C963FB21F63BD76A2AAAF66 ADE3560E2045CC1FA95F6EB51C9F7159FBDD0FA8FCDFC633B BBB04F1C8E9F248E2470707A322B333BC3DB838BA4CAA362% 2C26%20Jun%202008%2015%3A24%3A29%20-0000&PWAX MLData=%3CPWACALLBACK%3E%3CINPUT%20NAME%3D%22idIn formational%22%3E%3C%2FINPUT%3E%3CINPUT%20NAME%3D %22idOperation%22%3ECreateWeb%3C%2FINPUT%3E%3CINP UT%20NAME%3D%22idProjectUID%22%3Ed25dd736-bd24-44 5e-a6d2-8b792cd1bf4b%3C%2FINPUT%3E%3CINPUT%20NAME %3D%22idProjectName%22%3E%3C%2FINPUT%3E%3CINPUT%2 0NAME%3D%22idWSSServerUID%22%3E9829e40f-01e8-4dae -a49b-16bc2b4eb610%3C%2FINPUT%3E%3CINPUT%20NAME%3 D%22idWSSWebFullURL%22%3Ehttp%3A%2F%2Fukp12%2Fpwa %2FTest%20Project%3C%2FINPUT%3E%3C%2FPWACALLBACK% 3E%0D%0A
The posted request is translated as:
__REQUESTDIGEST=
0xB55C7C12C963FB21F63BD76A2AAAF66ADE3560E2045CC1F
A95F6EB51C9F7159FBDD0FA8FCDFC633BBBB04F1C8E9F248E
2470707A322B333BC3DB838BA4CAA362,26
Jun 2008 15:24:29 -0000
PWAXMLData=
<PWACALLBACK>
<INPUT NAME="idInformational"></INPUT>
<INPUT NAME="idOperation">CreateWeb</INPUT>
<INPUT NAME="idProjectUID">d25dd736-bd24-445e-a6d2-8b792cd1bf4b</INPUT>
<INPUT NAME="idProjectName"></INPUT>
<INPUT NAME="idWSSServerUID">9829e40f-01e8-4dae-a49b-16bc2b4eb610</INPUT>
<INPUT NAME="idWSSWebFullURL">http://ukp12/pwa/Test Project</INPUT>
</PWACALLBACK>
Which is quite readable and clearly indicates that it is asking for the method CreateWeb to be called, with the ProjectUID, ProjectName, WSSServerUID and WSSWebFullUrl. Everything you need to create a subweb in SharePoint.

Here is the response from Project Server:
HTTP/1.1 200 OK
Cache-Control: private, no-store
Content-Length: 84
Content-Type: text/html; charset=utf-8
Server: Microsoft-IIS/6.0
MicrosoftSharePointTeamServices: 12.0.0.4518
X-Powered-By: ASP.NET
X-AspNet-Version: 2.0.50727
Set-Cookie:WSS_KeepSessionAuthenticated=80; path=/
Set-Cookie: MSOWebPartPage_AnonymousAccessCookie=80;
expires=Thu, 26-Jun-2008 15:54:52 GMT; path=/
expires=Thu, 26-Jun-2008 15:34:52 GMT; path=/; HttpOnly
Date: Thu, 26 Jun 2008 15:26:32 GMT
And the content of that:
<PWARETURN><DATA ID="idError">-1</DATA><DATA ID="idMessage">Error</DATA></PWARETURN>
Which matches what we are seeing in our dialog box on the web page: “Error”.

The interesting thing here is the timing of that:
Request start time: Thu, 26 Jun 2008 16:24:52
Connecting delay: 0 ms
Headers exchange delay: 99908 ms
Data transmission delay: 0 ms
99.9 Seconds. Which matches our observation of 100 seconds to the error being shown.

The SharePoint log file for 100 seconds after the request was made includes this:
06/26/2008 16:26:32.48 w3wp.exe (0x1488) 0x14EC Project Server Project Server - General 8mqg Exception System.Net.WebException: The operation has timed out at System.Web.Services.Protocols.WebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.HttpWebClientProtocol.GetWebResponse(WebRequest request) at Microsoft.Office.Project.Server.WebServiceProxy.PSIProxyBase.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters) at Microsoft.Office.Project.Server.WebServiceProxy.PSIProxyBase.InvokePSI(String serviceName, String methodName, Object[] parameters)
Perfect! Now we’re getting somewhere. “The operation had timed out”, now just where does that happen and why? More to the point, what can I do to make it not happen?

Out comes .Net Reflector and I start with the ManageWSS.aspx that we were sending the request to… let’s see where that leads:
Microsoft.Office.Project.PWA.ApplicationPages.WSSAdminPage.ctor()
Microsoft.Office.Project.PWA.ApplicationPages.WSSAdminPage.PJWebPage_Onload()
Microsoft.Office.Project.PWA.ApplicationPages.WSSAdminPage.ProcessCallback(string
arg)
Microsoft.Office.Project.PWA.ApplicationPages.ManageWSSCallBack.ManageWSSCallBack()
Microsoft.Office.Project.PWA.ApplicationPages.ManageWSSCallBack.CreateWeb()
Microsoft.Office.Project.Server.WebServiceProxy.WssInterop.CreateWssSite(Guid,
projectUID, Guid wssServerUID, string wssWebFullUrl, int
webTemplateLcid, string webTemplateName)
Microsoft.Office.Project.Server.WebServiceProxy.PSIProxyBase.InvokePSI(string
serviceName, string methodName, object[] parameters)
System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(string
methodName, object[] parameters)
Microsoft.Office.Project.Server.WebServiceProxy.PSIProxyBase.GetWebRequest(Uri
uri)
System.Web.Services.Protocols.WebClientProtocol.timeout
System.Web.Services.Protocols.WebClientProtocol.Timeout
System.Web.Services.Protocols.WebClientProtocol.ctor().timeout =
0×186a0 (which is 100,000 milliseconds in Hex = 100 seconds we are
witnessing).
The second bolded line above shows where the 100 second timeout is coming from and that is documented here: http://msdn.microsoft.com/en-us/library/ms998562.aspx#scalenetchapt10_topic14

The first bolded line above shows the point in the PWA code that the WebRequest object is created. This is the point at which the webRequest.Timeout could be changed.

I looked quite thoroughly at this section of code and there is nothing in the code that allows the Timeout to be configured externally, as nowhere in the code is there anything to read in a configuration value and apply it to the webRequest instance.

So unless I am wrong it would appear that Microsoft Project Servers’ PSI (Project Server Interface) API is hard-limited to timeout at 100 seconds. If any PSI call takes longer than this then the PSIProxyBase class will throw an exception and cancel the underlying call.

As I saw, my template may be large but it is a perfectly feasible scenario that a PSI call such as that to create a Project Workspace could take more than the 100 seconds that is hard-wired by default.

Unfortunately, as I have no means to modify Microsoft’s code it would appear that unless they issue a hotfix this means that there is an implicit limitation on the size/complexity of a site template for use when provisioning new Project Workspaces. It isn’t a hard limit, it’s relative to the performance and load of the server, and if provisioning and syncing permissiongs takes more than 90 seconds then you are likely to hit this limit and the provisioning will fail without a clear error message (the generic error message we saw is thrown when any unknown exception is encountered).

The only advice I can give for this is to break out the template into SharePoint Features and merely activate them against the template. However I know in our scenario this doesn’t help as the template bloat came from Workflow and it is a business requirement that the client should be able to maintain these Workflows using SharePoint Designer, which means we can’t author the Workflows in Visual Studio and so we can’t use Features.

Oh well, all of this doesn’t help me, but perhaps it might help you.