none
PSI LoginWindows Login call always returning false with SharePoint AAM enabled RRS feed

  • Question

  • I have two different Azure VMs, both running Project Server 2013 SP1 on top of SharePoint 2013 fully patched (up to, but not including SharePoint SP1). I'm using the Playbooks tool from the resource kit to try to restore some enterprise custom fields. One of the servers is using AAM, the other is not. Before I added the AAM rules, the Playbooks tool ran successfully. The server without AAM continues to function correctly with the Playbooks tool (both on server and remotely) using windows authentication. I did some digging, and I found some stacktraces of interest on each server. First, the server  without AAM, which functions correctly and will connect to the Playbooks tool:

    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x167C	SharePoint Foundation	Monitoring	nasq	Medium	Entering monitored scope (Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")). Parent No	
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x167C	SharePoint Foundation	Logging Correlation Data	xmnv	Medium	Name=Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")	d27d989d-eb59-a008-682f-3b2435b23db7
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x167C	SharePoint Foundation	Authentication Authorization	agb9s	Medium	Non-OAuth request. IsAuthenticated=False, UserIdentityName=, ClaimsCount=0	d27d989d-eb59-a008-682f-3b2435b23db7
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x167C	SharePoint Foundation	Micro Trace	uls4	Medium	Micro Trace Tags: 0 nasq,2 agb9s	d27d989d-eb59-a008-682f-3b2435b23db7
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x167C	SharePoint Foundation	Monitoring	b4ly	Medium	Leaving Monitored Scope (Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")). Execution Time=3.2662	d27d989d-eb59-a008-682f-3b2435b23db7
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x0E94	SharePoint Foundation	Monitoring	nasq	Medium	Entering monitored scope (Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")). Parent No	
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x0E94	SharePoint Foundation	Logging Correlation Data	xmnv	Medium	Name=Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")	d27d989d-eb59-a008-682f-31c25bf2a742
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x0E94	SharePoint Foundation	Micro Trace	uls4	Medium	Micro Trace Tags: 0 nasq	d27d989d-eb59-a008-682f-31c25bf2a742
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x0E94	SharePoint Foundation	Monitoring	b4ly	Medium	Leaving Monitored Scope (Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")). Execution Time=0.5129	d27d989d-eb59-a008-682f-31c25bf2a742
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x1AB8	SharePoint Foundation	Monitoring	nasq	Medium	Entering monitored scope (Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")). Parent No	
    08/10/2016 18:21:43.71	w3wp.exe (0x1F64)	0x1AB8	SharePoint Foundation	Logging Correlation Data	xmnv	Medium	Name=Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")	d27d989d-eb59-a008-682f-39a2252ad7d5
    08/10/2016 18:21:43.72	w3wp.exe (0x1F64)	0x1AB8	SharePoint Foundation	Authentication Authorization	agb9s	Medium	Non-OAuth request. IsAuthenticated=True, UserIdentityName=0#.w|ps2013\oisin, ClaimsCount=22	d27d989d-eb59-a008-682f-39a2252ad7d5
    08/10/2016 18:21:43.72	w3wp.exe (0x1F64)	0x1AB8	SharePoint Foundation	Logging Correlation Data	xmnv	Medium	Site=/	d27d989d-eb59-a008-682f-39a2252ad7d5
    08/10/2016 18:21:43.74	w3wp.exe (0x1F64)	0x1AB8	Project Server	Security	aebez	Medium	Entered GetIdentityEncodedClaims for Identity (name=0#.w|ps2013\oisin, isAuthenticated=True, authenticationType=Federation)	d27d989d-eb59-a008-682f-39a2252ad7d5
    08/10/2016 18:21:43.74	w3wp.exe (0x1F64)	0x1AB8	Project Server	Project Server Database	ah91z	Medium	Successfully got the connection string (database name=[ProjectWebAppDev], id=bac060b4-8f46-43f7-b502-a9d974b7029c, type=Consolidated). Requested access level=ReadWrite: Data Source=ps2013;Initial Catalog=ProjectWebAppDev;Integrated Security=True;Enlist=False;Pooling=True;Min Pool Size=0;Max Pool Size=100;Connect Timeout=15	d27d989d-eb59-a008-682f-39a2252ad7d5
    08/10/2016 18:21:43.77	w3wp.exe (0x1F64)	0x1AB8	SharePoint Foundation	Micro Trace	uls4	Medium	Micro Trace Tags: 0 nasq,5 agb9s,16 aebez,0 ah91z	d27d989d-eb59-a008-682f-39a2252ad7d5
    08/10/2016 18:21:43.77	w3wp.exe (0x1F64)	0x1AB8	SharePoint Foundation	Monitoring	b4ly	Medium	Leaving Monitored Scope (Request (POST:http://ps2013:80/ppp/_vti_bin/PSI/LoginWindows.asmx:Login")). Execution Time=59.8933	d27d989d-eb59-a008-682f-39a2252ad7d5
    08/10/2016 18:21:43.78	w3wp.exe (0x1F64)	0x1EEC	SharePoint Foundation	Monitoring	nasq	Medium	Entering monitored scope (Request (POST:http://ps2013:80/ppp/_vti_bin/psi/view.asmx:ReadViewSummaries")). Parent No	
    

    As we can see, there is an initial connection to the LoginWindows service  with an anonymous context, and then in an authenticated context, leading to the first call to view.asmx:ReadViewSummaries.

    Now, on the server that is failing, the initial call fails because deep in the stack, SPWeb.InitWeb throws an E_ACCESSDENIED, and it unwinds until the Login call returns false, by default. Here's the stack from ULS:

    System.UnauthorizedAccessException: Access is denied. (Exception from HRESULT: 0x80070005 (E_ACCESSDENIED)), StackTrace:   
     at Microsoft.SharePoint.SPWeb.InitWeb()    
     at Microsoft.SharePoint.SPWeb.get_RegionalSettings()    
     at Microsoft.Office.Project.PWA.PJContext.GetRegionalSettings(SPWeb web)    
     at Microsoft.Office.Project.PWA.PJContext.get_RegionalSettings()    
     at Microsoft.Office.Project.PWA.PJContext.get_LocaleCulture()    
     at Microsoft.Office.Project.PWA.PJContext.Initialize(Boolean isWebServiceCall)    
     at Microsoft.Office.Project.PWA.PJContext..ctor(Boolean isWebServiceCall, SPWeb spWeb)    
     at Microsoft.Office.Project.PWA.PJContext.GetContext(Boolean isWebServiceCall, Boolean ignoreCachedContext, SPWeb web)    
     at Microsoft.Office.Project.PWA.PJContext.GetContext(Boolean isWebServiceCall, Boolean ignoreCachedContext)    
     at Microsoft.Office.Project.Server.PSIAuth.LoginWindowsImpl.Login(WebService ws)    
     at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)    
     at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)    
     at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)    
     at System.Web.Services.Protocols.LogicalMethodInfo.Invoke(Object target, Object[] values)    
     at System.Web.Services.Protocols.WebServiceHandler.Invoke()    
     at System.Web.Services.Protocols.WebServiceHandler.CoreProcessRequest()    
     at System.Web.Services.Protocols.SyncSessionlessHandler.ProcessRequest(HttpContext context)    
     at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()    
     at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)    
     at System.Web.HttpApplication.PipelineStepManager.ResumeSteps(Exception error)    
     at System.Web.HttpApplication.BeginProcessRequestNotification(HttpContext context, AsyncCallback cb)    
     at System.Web.HttpRuntime.ProcessRequestNotificationPrivate(IIS7WorkerRequest wr, HttpContext context)    
     at System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)    
     at System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)    
     at System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr pHandler, RequestNotificationStatus& notificationStatus)    
     at System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr pHandler, RequestNotificationStatus& notificationStatus)    
     at System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)    
     at System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)
    

    This happens in the initial, unauthenticated call to LoginWindows:Login. Is this a known issue? I've tried all sorts of things with AAM but I cannot remove AAM. 


    • Edited by Oisín Grehan Wednesday, August 10, 2016 7:00 PM add blank lines
    Wednesday, August 10, 2016 6:54 PM

All replies

  • Oh, and the AAM server is using SSL but even adding a non-SSL internal url through AAM (and the appropriate binding) still doesn't help. I can access the PWA site perfectly from any browser, local or remote, http or https, so I know the AAM is correct the playbooks tool continually fails to login.
    Wednesday, August 10, 2016 6:59 PM