IIS reset causes 401 errors on high trust app

Question

I have a high trust provider hosted SharePoint 2013 app which has started giving 401 errors when connecting to SharePoint using CSOM. The app is hosted on IIS on the same server as the SharePoint installation (Foundation version). To fix the error the only way I've found is to re-upload the package to the app catalog site (uploading exactly the same package file each time works) and then the app starts working. Doing an IIS reset breaks it again.

Other things I've tried to get the app working:

• IIS reset
• recycling the security token service application pool
• redeploying the web app to IIS

Other things I've tried to get the app to error again:

• recycling the security token service application pool
• recycling any other relevant application pools (for the SP site the app is deployed to, for the app)
• restarting the site in IIS

I get two errors in the application logs when the 401 error occurs. It looks like the 401 causes the security token not to be issued? Maybe these events are the wrong way around in the log and it's a problem with the security token service?

First error in windows application logs:

Log Name:      Application
Source:        ASP.NET 4.0.30319.0
Date:          22/08/2015 19:21:25
Event ID:      1309
Task Category: Web Event
Level:         Warning
Keywords:      Classic
User:          N/A
Computer:      SERVER
Description:
Event code: 3005 
Event message: An unhandled exception has occurred. 
Event time: 22/08/2015 19:21:25 
Event time (UTC): 22/08/2015 18:21:25 
Event ID: 1372aecda6e4497aadbf0cd015dea96e 
Event sequence: 6 
Event occurrence: 1 
Event detail code: 0 

Exception information: 
    Exception type: WebException 
    Exception message: The remote server returned an error: (401) Unauthorized.
   at System.Net.HttpWebRequest.GetResponse()
...

Request information: 
...
    Is authenticated: True 
    Authentication Type: NTLM 
...

Thread information:
...
    Is impersonating: False 
...

Second error in windows application logs:

Log Name:      Application
Source:        Microsoft-SharePoint Products-SharePoint Foundation
Date:          22/08/2015 19:37:12
Event ID:      8306
Task Category: Claims Authentication
Level:         Error
...
Description:
An exception occurred when trying to issue security token: The server was unable to process the request due to an internal error.  For more information about the error, either turn on IncludeExceptionDetailInFaults (either from ServiceBehaviorAttribute or from the <serviceDebug> configuration behavior) on the server in order to send the exception information back to the client, or turn on tracing as per the Microsoft .NET Framework SDK documentation and inspect the server trace logs..
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="Microsoft-SharePoint Products-SharePoint Foundation" Guid="{6FB7E0CD-52E7-47DD-997A-241563931FC2}" />
    <EventID>8306</EventID>
    <Version>15</Version>
    <Level>2</Level>
    <Task>47</Task>
    <Opcode>0</Opcode>
    <Keywords>0x4000000000000000</Keywords>
    <TimeCreated SystemTime="2015-08-22T18:37:12.445385200Z" />
    <EventRecordID>507002</EventRecordID>
    <Correlation ActivityID="{FF8D269D-2393-005B-6978-9C53DDA19D75}" />
    <Execution ProcessID="17148" ThreadID="13064" />
    <Channel>Application</Channel>
    <Computer>SERVER</Computer>
    <Security UserID="S-1-5-21-2510812899-823872513-1904906047-1011" />
  </System>
  <EventData>
    <Data Name="string0">The server was unable to process the request due to an internal error.  For more information about the error, either turn on IncludeExceptionDetailInFaults (either from ServiceBehaviorAttribute or from the &lt;serviceDebug&gt; configuration behavior) on the server in order to send the exception information back to the client, or turn on tracing as per the Microsoft .NET Framework SDK documentation and inspect the server trace logs.</Data>
  </EventData>
</Event>

EDIT 1: I found the following in ULS logs:

08/28/2015 09:40:11.19  w3wp.exe (0x1F60)                           0x2BF4  SharePoint Foundation           DistributedCache                ah24w   Unexpected  Unexpected Exception in SPDistributedCachePointerWrapper::InitializeDataCacheFactory for usage 'DistributedLogonTokenCache' - Exception 'Microsoft.ApplicationServer.Caching.DataCacheException: ErrorCode<ERRCA0009>:SubStatus<ES0001>:Cache referred to does not exist. Contact administrator or use the Cache administration tool to create a Cache.     at Microsoft.ApplicationServer.Caching.DataCache.ThrowException(ResponseBody respBody, RequestBody reqBody)     at Microsoft.ApplicationServer.Caching.DataCacheFactory.GetCacheProperties(RequestBody request, IClientChannel channel)     at Microsoft.ApplicationServer.Caching.DataCacheFactory.GetCache(String cacheName)     at Microsoft.SharePoint.DistributedCaching.SPDistributedCachePointerWrapper.InitializeDataCacheFactory()'.   355a289d-b313-005b-6978-9d3a0e9cfe6d
08/28/2015 09:40:11.19  w3wp.exe (0x1F60)                           0x2BF4  SharePoint Foundation           DistributedCache                air4g   Monitorable Token Cache: Failed to initialize SPDistributedSecurityTokenCache  Exception: 'Microsoft.ApplicationServer.Caching.DataCacheException: ErrorCode<ERRCA0009>:SubStatus<ES0001>:Cache referred to does not exist. Contact administrator or use the Cache administration tool to create a Cache.     at Microsoft.ApplicationServer.Caching.DataCache.ThrowException(ResponseBody respBody, RequestBody reqBody)     at Microsoft.ApplicationServer.Caching.DataCacheFactory.GetCacheProperties(RequestBody request, IClientChannel channel)     at Microsoft.ApplicationServer.Caching.DataCacheFactory.GetCache(String cacheName)     at Microsoft.SharePoint.DistributedCaching.SPDistributedCachePointerWrapper.InitializeDataCacheFactory()     at Microsoft.SharePoint.DistributedCaching.SPDistributedCache..ctor(String nam... 355a289d-b313-005b-6978-9d3a0e9cfe6d
08/28/2015 09:40:11.19* w3wp.exe (0x1F60)                           0x2BF4  SharePoint Foundation           DistributedCache                air4g   Monitorable ...e, TimeSpan timeToLive, SPDistributedCacheContainerType containerType, Boolean encryptData)     at Microsoft.SharePoint.IdentityModel.SPDistributedSecurityTokenCache..ctor(String name, TimeSpan timeToLive, SPDistributedCacheContainerType containerType, Boolean encrptyData, TimeSpan minimumTokenExpirationWindow)     at Microsoft.SharePoint.IdentityModel.SPDistributedSecurityTokenCacheInitializer.Init(Object state)'.   355a289d-b313-005b-6978-9d3a0e9cfe6d

And then I found this article. My SP server had no caches at all when I ran Get-Cache, so I ran the following commands:

Connect-AFCacheClusterConfiguration
Restart-AFCacheCluster

The default cache then appeared, and then I created the DistributedLogonTokenCache and SPDistributedSecurityTokenCache as described in the article with New-Cache -CacheName DistributedLogonTokenCache...

After restarting iis and trying the app again, I no longer had the cache errors in the ULS logs but the app is getting the same 401 errors. Here's the ULS logs now when I run the app:

08/28/2015 11:36:44.63  w3wp.exe (0x40A0)                           0x3BC4  SharePoint Foundation           Claims Authentication           ah25l   Medium      SPJsonWebSecurityBaseTokenHandler: ValidateActorIsSelfIssuer! Issuer 'SP1 Prod High Trust Cert' is not self issuer. e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x40A0)                           0x3BC4  SharePoint Foundation           Claims Authentication           ae0td   Unexpected  Mapping operations are not supported. There is no registered mapper e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x40A0)                           0x3BC4  SharePoint Foundation           Claims Authentication           af3zp   Unexpected  STS Call Claims Saml: Problem getting output claims identity. Exception: 'System.NotSupportedException: There is no identity claim mapper registered. The mapping operation is not supported.     at Microsoft.SharePoint.IdentityModel.SPIdentityClaimMapperOperations.GetClaimFromExternalMapper(Uri contextUri, List`1 claims)     at Microsoft.SharePoint.IdentityModel.SPIdentityClaimMapperOperations.ResolveUserIdentityClaim(Uri contextUri, ClaimCollection inputClaims)     at Microsoft.SharePoint.IdentityModel.SPIdentityClaimMapperOperations.GetIdentityClaim(Uri contextUri, ClaimCollection inputClaims, SPCallingIdentityType callerType)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.GetLogonIdentityClaim(SPRequestInfo requestInfo, IClaimsIdentity inputIdentity, IClaimsIdentity out... e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63* w3wp.exe (0x40A0)                           0x3BC4  SharePoint Foundation           Claims Authentication           af3zp   Unexpected  ...putIdentity, SPCallingIdentityType callerType)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.EnsureSharePointClaims(SPRequestInfo requestInfo, IClaimsIdentity outputIdentity, SPCallingIdentityType callerType)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.AugmentOutputIdentityForRequest(SPRequestInfo requestInfo, IClaimsIdentity outputIdentity)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.GetOutputClaimsIdentity(IClaimsPrincipal principal, RequestSecurityToken request, Scope scope)'.    e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x40A0)                           0x3BC4  SharePoint Foundation           Claims Authentication           fo1t    Monitorable STS Call: Failed to issue new security token. Exception: System.NotSupportedException: There is no identity claim mapper registered. The mapping operation is not supported.     at Microsoft.SharePoint.IdentityModel.SPIdentityClaimMapperOperations.GetClaimFromExternalMapper(Uri contextUri, List`1 claims)     at Microsoft.SharePoint.IdentityModel.SPIdentityClaimMapperOperations.ResolveUserIdentityClaim(Uri contextUri, ClaimCollection inputClaims)     at Microsoft.SharePoint.IdentityModel.SPIdentityClaimMapperOperations.GetIdentityClaim(Uri contextUri, ClaimCollection inputClaims, SPCallingIdentityType callerType)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.GetLogonIdentityClaim(SPRequestInfo requestInfo, IClaimsIdentity inputIdentity, IClaimsIdentity outputIdentity, SPCa... e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63* w3wp.exe (0x40A0)                           0x3BC4  SharePoint Foundation           Claims Authentication           fo1t    Monitorable ...llingIdentityType callerType)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.EnsureSharePointClaims(SPRequestInfo requestInfo, IClaimsIdentity outputIdentity, SPCallingIdentityType callerType)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.AugmentOutputIdentityForRequest(SPRequestInfo requestInfo, IClaimsIdentity outputIdentity)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.GetOutputClaimsIdentity(IClaimsPrincipal principal, RequestSecurityToken request, Scope scope)     at Microsoft.IdentityModel.SecurityTokenService.SecurityTokenService.Issue(IClaimsPrincipal principal, RequestSecurityToken request)     at Microsoft.SharePoint.IdentityModel.SPSecurityTokenService.Issue(IClaimsPrincipal principal, RequestSecurityToken request) e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x40A0)                           0x3BC4  SharePoint Foundation           Monitoring                      b4ly    Medium      Leaving Monitored Scope (ExecuteSecurityTokenServiceOperationServer). Execution Time=18.0120657793099   e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x1458)                           0x0A68  SharePoint Foundation           Claims Authentication           fsq7    High        SPSecurityContext: Request for security token failed with exception: System.ServiceModel.FaultException: The server was unable to process the request due to an internal error.  For more information about the error, either turn on IncludeExceptionDetailInFaults (either from ServiceBehaviorAttribute or from the <serviceDebug> configuration behavior) on the server in order to send the exception information back to the client, or turn on tracing as per the Microsoft .NET Framework SDK documentation and inspect the server trace logs.     at Microsoft.IdentityModel.Protocols.WSTrust.WSTrustChannel.ReadResponse(Message response)     at Microsoft.IdentityModel.Protocols.WSTrust.WSTrustChannel.Issue(RequestSecurityToken rst, RequestSecurityTokenResponse& rstr)     at Microsoft.IdentityModel.Protoco... e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63* w3wp.exe (0x1458)                           0x0A68  SharePoint Foundation           Claims Authentication           fsq7    High        ...ls.WSTrust.WSTrustChannel.Issue(RequestSecurityToken rst)     at Microsoft.SharePoint.SPSecurityContext.SecurityTokenForContext(Uri context, Boolean bearerToken, SecurityToken onBehalfOf, SecurityToken actAs, SecurityToken delegateTo, SPRequestSecurityTokenProperties properties)  e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x1458)                           0x0A68  SharePoint Foundation           Claims Authentication           8306    Critical    An exception occurred when trying to issue security token: The server was unable to process the request due to an internal error.  For more information about the error, either turn on IncludeExceptionDetailInFaults (either from ServiceBehaviorAttribute or from the <serviceDebug> configuration behavior) on the server in order to send the exception information back to the client, or turn on tracing as per the Microsoft .NET Framework SDK documentation and inspect the server trace logs..   e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x1458)                           0x0A68  SharePoint Foundation           Monitoring                      b4ly    High        Leaving Monitored Scope ([S2S] Getting token from STS and setting Thread Identity). Execution Time=114.067849405441 e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x1458)                           0x0A68  SharePoint Foundation           Monitoring                      b4ly    High        Leaving Monitored Scope (Application Authentication Pipeline). Execution Time=133.320016929526  e660289d-7305-005b-6978-98a016b54a82
08/28/2015 11:36:44.63  w3wp.exe (0x1458)                           0x0A68  SharePoint Foundation           Application Authentication      ajezs   High        SPApplicationAuthenticationModule: Error authenticating request, Error details { Header: {0}, Body: {1} }.  Available parameters: 3001000;reason="There has been an error authenticating the request.";category="invalid_client" {"error_description":"The server was unable to process the request due to an internal error.  For more information about the error, either turn on IncludeExceptionDetailInFaults (either from ServiceBehaviorAttribute or from the <serviceDebug> configuration behavior) on the server in order to send the exception information back to the client, or turn on tracing as per the Microsoft .NET Framework SDK documentation and inspect the server trace logs."} .    e660289d-7305-005b-6978-98a016b54a82

So I think the first two lines are the important ones; Issuer 'SP1 Prod High Trust Cert' is not self issuer and There is no registered mapper. I can't figure out if the first one is an error or just information, and the second one I can't find any information about.

Maybe there are real app authentication issues and the fact that it works fine after deploying a new package is a bug?

EDIT 2 (01/09/15)

@johnnycardy drew my attention to the fact that the high trust app should not work at all with Foundation version. So now I am trying to get a licence to upgrade the SP version to test if it works ok with Sharepoint Server 2013 instead.

Answer 1

This might be problem in Security Token Service.Go to IIS and to SecurityTokenServiceApplication(Web application). Click on test settings and see if same error is displayed.

Answer 2

So I think the problem here is that I am trying to use a high trust app with SharePoint Foundation...but there seems to be a hacky workaround. Using casperjs to re-upload the app package to SharePoint before running the app.

My TERRIBLE casperjs script is below, which works fine for me. A note about casperjs; I dropped the phantomjs exe into System32, but casperjs seems to not like being on a path with spaces in Windows so I've put it in C:\Windows. This problem also applies to the location of the package file, so I've put it into the same directory as the casperjs script (which can be anywhere).

var url = 'https://yourdomain/sites/appcatalog/_layouts/15/start.aspx#/AppCatalog/Forms/AllItems.aspx'
var file = 'sharepoint-package.app'
var user = 'username'
var pass = 'password'

var casper = require('casper').create();

casper.start();
casper.setHttpAuth(user, pass);

casper.thenOpen(url, function() {
  this.echo(this.getTitle());
  this.waitForSelector('#idHomePageNewDocument-WPQ2', function() {
    this.echo("Found selector");
  });
});

casper.thenClick('#idHomePageNewDocument-WPQ2', function() {
  this.echo("Clicked button");
  this.waitForSelector('.ms-dlgFrameContainer > iframe', function() {
    this.echo("Got the iframe");
  });
});

casper.withFrame(1, function() {
  this.waitForSelector('#aspnetForm', function() {
    this.echo("Found form");
    this.fill('#aspnetForm', {
      'ctl00$PlaceHolderMain$ctl01$ctl04$InputFile': file,
    }, false);
    this.wait(3000, function() {
      this.click('#ctl00_PlaceHolderMain_ctl00_RptControls_btnOK');
      this.echo("Clicked button");
    });
  });
});

casper.run();