search

IdentityServer / IdentityServer3

OpenID Connect Provider and OAuth 2.0 Authorization Server Framework for ASP.NET 4.x/Katana
https://identityserver.github.io/Documentation/
Apache License 2.0
2.01k stars 763 forks source link

.Net 4.7 Breaks AntiForgery Token Cookie Header #3741

Closed AdamDotNet closed 7 years ago

AdamDotNet commented 7 years ago

Question / Issue

I have IdentityServer3, Nuget Version 2.6 installed on an Asp.Net MVC 5, .Net 4.6.2 app. Changing nothing other than installing KB3186539 on Windows Server 2012 R2, I was no longer able to sign into our desktop product that uses the WPF browser control (with edge meta tag, so IE 11 on my Windows 10 x64 box). The client is authorized via Hyrbrid flow, client Id/Secret. Through the IdentityServer logging and Fiddler, it looks like cookie "SA.idsrv.xsrf" (SA is my prefix I configured) is not being sent as part of submitting the username/password. Our app sends a sign out request first in order to flush cookies, then the sign in request.

Upon uninstalling KB3186539 (.Net 4.7) on the server, the app could sign in again. The MVC app was compiled for .Net 4.6.2 throughout this whole process. Full web browsers using Implicit authorization flow for signing into websites works fine, mysteriously enough.

The short story of the log file seems to be as the following:

  1. App launched, and sent a signout request. /Identity/connect/endsession is hit, followed by /Identity/logout with the right SignOutMessage.
  2. /Identity/connect/authorize endpoint is hit, a SignInMessage is produced.
  3. GET Request /Identity/login, it sure looks like Set-Cookie, SA.idsrv.xsrf is happening here like it should...
  4. POST Request /Identity/login, and "Body" includes idsrv.xsrf, but "Cookie" does not.
  5. [Error] AntiForgery validation failed -- returning error page

I hope this will help out. It's always a shame when .Net breaks things.

Relevant parts of the log file (I tried to keep this slim, but 610 lines remain)

2017-06-13 15:49:50.796 -06:00 [Debug] HTTP Request
{
  "Method": "GET",
  "Url": "https://<ourUrl>/Identity/connect/endsession?post_logout_redirect_uri=oob%3A%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging",
  "Headers": {
    "Connection": [
      "Keep-Alive"
    ],
    "Accept": [
      "*/*"
    ],
    "Accept-Encoding": [
      "gzip, deflate"
    ],
    "Accept-Language": [
      "en-US"
    ],
    "Host": [
      "<ourUrl>"
    ],
    "User-Agent": [
      "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)"
    ],
    "UA-CPU": [
      "AMD64"
    ]
  },
  "Body": ""
}
2017-06-13 15:49:50.796 -06:00 [Debug] [2017-06-13T21:49:50.7961538Z] Request received, Method=GET, Url=https://<ourUrl>/Identity/connect/endsession?post_logout_redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging, Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='https://<ourUrl>/Identity/connect/endsession?post_logout_redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging'
2017-06-13 15:49:50.797 -06:00 [Debug] [2017-06-13T21:49:50.7961538Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=DependencyScopeHandler.SendAsync
2017-06-13 15:49:50.797 -06:00 [Debug] [2017-06-13T21:49:50.7971532Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=PassiveAuthenticationMessageHandler.SendAsync
2017-06-13 15:49:50.797 -06:00 [Debug] [2017-06-13T21:49:50.7971532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Route='controller:EndSession,action:Logout'', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:50.797 -06:00 [Debug] [2017-06-13T21:49:50.7971532Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='EndSession', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:50.797 -06:00 [Debug] [2017-06-13T21:49:50.7971532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:50.797 -06:00 [Debug] [2017-06-13T21:49:50.7971532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:50.799 -06:00 [Debug] [2017-06-13T21:49:50.7991532Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='IdentityServer3.Core.Endpoints.EndSessionController', Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:50.799 -06:00 [Debug] [2017-06-13T21:49:50.7991532Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='IdentityServer3.Core.Endpoints.EndSessionController', Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:50.799 -06:00 [Debug] [2017-06-13T21:49:50.7991532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=EndSessionController.ExecuteAsync
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.7991532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Selected action 'Logout()'', Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='The authentication filter did not encounter an error or set a principal.', Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=Begin, Category='System.Web.Http.ModelBinding', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=End, Category='System.Web.Http.ModelBinding', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:50.800 -06:00 [Debug] [2017-06-13T21:49:50.8001533Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Action filter for 'Logout()'', Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.801 -06:00 [Debug] [2017-06-13T21:49:50.8011532Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.801 -06:00 [Debug] [2017-06-13T21:49:50.8011532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Action filter for 'Logout()'', Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.801 -06:00 [Debug] [2017-06-13T21:49:50.8011532Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.801 -06:00 [Debug] [2017-06-13T21:49:50.8011532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Action='Logout()'', Operation=ApiControllerActionInvoker.InvokeActionAsync
2017-06-13 15:49:50.801 -06:00 [Debug] [2017-06-13T21:49:50.8011532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Invoking action 'Logout()'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:50.801 -06:00 [Information] Start end session request
2017-06-13 15:49:50.801 -06:00 [Information] Start end session request validation
2017-06-13 15:49:50.801 -06:00 [Information] "End session request validation success"
"{
  \"SubjectId\": \"unknown\",
  \"Raw\": {
    \"post_logout_redirect_uri\": \"oob://desktopclient/sawtoothsoftware/staging\"
  }
}"
2017-06-13 15:49:50.801 -06:00 [Information] End end session request
2017-06-13 15:49:50.801 -06:00 [Debug] [2017-06-13T21:49:50.8011532Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Action returned 'IdentityServer3.Core.Results.LogoutResult'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:50.801 -06:00 [Information] Redirecting to logout page
2017-06-13 15:49:50.801 -06:00 [Debug] Protecting message: "{\"Created\":636329873908011532}"
2017-06-13 15:49:50.802 -06:00 [Debug] [2017-06-13T21:49:50.8021532Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=ApiControllerActionInvoker.InvokeActionAsync, Status=302 (Redirect)
2017-06-13 15:49:50.802 -06:00 [Debug] [2017-06-13T21:49:50.8021532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Action filter for 'Logout()'', Operation=NoCacheAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:50.802 -06:00 [Debug] [2017-06-13T21:49:50.8021532Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=NoCacheAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:50.802 -06:00 [Debug] [2017-06-13T21:49:50.8021532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Action filter for 'Logout()'', Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:50.802 -06:00 [Debug] [2017-06-13T21:49:50.8021532Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:50.802 -06:00 [Debug] [2017-06-13T21:49:50.8021532Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=EndSessionController.ExecuteAsync, Status=302 (Redirect)
2017-06-13 15:49:50.802 -06:00 [Debug] [2017-06-13T21:49:50.8021532Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=PassiveAuthenticationMessageHandler.SendAsync, Status=302 (Redirect)
2017-06-13 15:49:50.803 -06:00 [Debug] [2017-06-13T21:49:50.8031533Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=DependencyScopeHandler.SendAsync, Status=302 (Redirect)
2017-06-13 15:49:50.803 -06:00 [Debug] [2017-06-13T21:49:50.8031533Z] Sending response, Status=302 (Redirect), Method=GET, Url=https://<ourUrl>/Identity/connect/endsession?post_logout_redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging, Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Message='Content-type='none', content-length=unknown'
2017-06-13 15:49:50.803 -06:00 [Debug] [2017-06-13T21:49:50.8031533Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=EndSessionController.Dispose
2017-06-13 15:49:50.803 -06:00 [Debug] [2017-06-13T21:49:50.8031533Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=bd1fd24c-ab76-4146-b3a4-c301c3bdb028, Operation=EndSessionController.Dispose
2017-06-13 15:49:50.803 -06:00 [Debug] HTTP Response
{
  "StatusCode": 302,
  "Headers": {
    "Content-Type": [
      "text/html"
    ],
    "Server": [
      "Microsoft-IIS/8.5"
    ],
    "Set-Cookie": [
      "SA.SignOutMessage.6c1cfc5fb050705cb7514ebf1b71d217=Pm4D6sjQT4oVOWhkBYELYSjcSmBrIe3cg2ZhxhuLr53DpmHAjH4K2oMfiDiUOHcFkM57WE70mT6jadKhNqaGkPNmwwY9nd-D7tdRslmVBbw; path=/Identity; secure; HttpOnly"
    ],
    "Location": [
      "https://<ourUrl>/Identity/logout?id=6c1cfc5fb050705cb7514ebf1b71d217"
    ],
    "Content-Length": [
      "0"
    ]
  },
  "Body": ""
}
2017-06-13 15:49:50.872 -06:00 [Debug] HTTP Request
{
  "Method": "GET",
  "Url": "https://<ourUrl>/Identity/logout?id=6c1cfc5fb050705cb7514ebf1b71d217",
  "Headers": {
    "Connection": [
      "Keep-Alive"
    ],
    "Accept": [
      "*/*"
    ],
    "Accept-Encoding": [
      "gzip, deflate"
    ],
    "Accept-Language": [
      "en-US"
    ],
    "Cookie": [
      "SA.SignOutMessage.6c1cfc5fb050705cb7514ebf1b71d217=Pm4D6sjQT4oVOWhkBYELYSjcSmBrIe3cg2ZhxhuLr53DpmHAjH4K2oMfiDiUOHcFkM57WE70mT6jadKhNqaGkPNmwwY9nd-D7tdRslmVBbw"
    ],
    "Host": [
      "<ourUrl>"
    ],
    "User-Agent": [
      "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)"
    ],
    "UA-CPU": [
      "AMD64"
    ]
  },
  "Body": ""
}
2017-06-13 15:49:50.872 -06:00 [Debug] [2017-06-13T21:49:50.8721541Z] Request received, Method=GET, Url=https://<ourUrl>/Identity/logout?id=6c1cfc5fb050705cb7514ebf1b71d217, Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='https://<ourUrl>/Identity/logout?id=6c1cfc5fb050705cb7514ebf1b71d217'
2017-06-13 15:49:50.872 -06:00 [Debug] [2017-06-13T21:49:50.8721541Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=DependencyScopeHandler.SendAsync
2017-06-13 15:49:50.872 -06:00 [Debug] [2017-06-13T21:49:50.8721541Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=PassiveAuthenticationMessageHandler.SendAsync
2017-06-13 15:49:50.872 -06:00 [Debug] [2017-06-13T21:49:50.8721541Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Route='MS_SubRoutes:System.Web.Http.Routing.IHttpRouteData[]'', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:50.872 -06:00 [Debug] [2017-06-13T21:49:50.8721541Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Authentication', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:50.872 -06:00 [Debug] [2017-06-13T21:49:50.8721541Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:50.872 -06:00 [Debug] [2017-06-13T21:49:50.8721541Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:50.874 -06:00 [Debug] [2017-06-13T21:49:50.8741543Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='IdentityServer3.Core.Endpoints.AuthenticationController', Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:50.874 -06:00 [Debug] [2017-06-13T21:49:50.8741543Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='IdentityServer3.Core.Endpoints.AuthenticationController', Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:50.874 -06:00 [Debug] [2017-06-13T21:49:50.8741543Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=AuthenticationController.ExecuteAsync
2017-06-13 15:49:50.874 -06:00 [Debug] [2017-06-13T21:49:50.8741543Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:50.874 -06:00 [Debug] [2017-06-13T21:49:50.8741543Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Selected action 'LogoutPrompt(String id)'', Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:50.874 -06:00 [Debug] [2017-06-13T21:49:50.8741543Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:50.874 -06:00 [Debug] [2017-06-13T21:49:50.8741543Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='The authentication filter did not encounter an error or set a principal.', Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=Begin, Category='System.Web.Http.ModelBinding', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=Begin, Category='System.Web.Http.ModelBinding', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Binding parameter 'id'', Operation=ModelBinderParameterBinding.ExecuteBindingAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=End, Category='System.Web.Http.ModelBinding', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Parameter 'id' bound to the value '6c1cfc5fb050705cb7514ebf1b71d217'', Operation=ModelBinderParameterBinding.ExecuteBindingAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=End, Category='System.Web.Http.ModelBinding', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Model state is valid. Values: id=6c1cfc5fb050705cb7514ebf1b71d217', Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Action filter for 'LogoutPrompt(String id)'', Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.875 -06:00 [Debug] [2017-06-13T21:49:50.8751537Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.876 -06:00 [Debug] [2017-06-13T21:49:50.8761532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Action filter for 'LogoutPrompt(String id)'', Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.876 -06:00 [Debug] [2017-06-13T21:49:50.8761532Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:50.876 -06:00 [Debug] [2017-06-13T21:49:50.8761532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Action='LogoutPrompt(id=6c1cfc5fb050705cb7514ebf1b71d217)'', Operation=ApiControllerActionInvoker.InvokeActionAsync
2017-06-13 15:49:50.876 -06:00 [Debug] [2017-06-13T21:49:50.8761532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Invoking action 'LogoutPrompt(id=6c1cfc5fb050705cb7514ebf1b71d217)'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:50.876 -06:00 [Information] Logout endpoint submitted
2017-06-13 15:49:50.876 -06:00 [Information] Clearing cookies
2017-06-13 15:49:50.876 -06:00 [Information] rendering logged out page
2017-06-13 15:49:50.877 -06:00 [Debug] [2017-06-13T21:49:50.8761532Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Action returned 'IdentityServer3.Core.Results.LoggedOutActionResult'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:50.879 -06:00 [Debug] [2017-06-13T21:49:50.8791540Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=ApiControllerActionInvoker.InvokeActionAsync, Status=200 (OK)
2017-06-13 15:49:50.879 -06:00 [Debug] [2017-06-13T21:49:50.8791540Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Action filter for 'LogoutPrompt(String id)'', Operation=NoCacheAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:50.879 -06:00 [Debug] [2017-06-13T21:49:50.8791540Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=NoCacheAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:50.879 -06:00 [Debug] [2017-06-13T21:49:50.8791540Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Action filter for 'LogoutPrompt(String id)'', Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:50.879 -06:00 [Debug] [2017-06-13T21:49:50.8791540Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:50.879 -06:00 [Debug] [2017-06-13T21:49:50.8791540Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=AuthenticationController.ExecuteAsync, Status=200 (OK)
2017-06-13 15:49:50.880 -06:00 [Debug] [2017-06-13T21:49:50.8791540Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=PassiveAuthenticationMessageHandler.SendAsync, Status=200 (OK)
2017-06-13 15:49:50.880 -06:00 [Debug] [2017-06-13T21:49:50.8801563Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=DependencyScopeHandler.SendAsync, Status=200 (OK)
2017-06-13 15:49:50.880 -06:00 [Debug] [2017-06-13T21:49:50.8801563Z] Sending response, Status=200 (OK), Method=GET, Url=https://<ourUrl>/Identity/logout?id=6c1cfc5fb050705cb7514ebf1b71d217, Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Message='Content-type='text/html; charset=utf-8', content-length=3513'
2017-06-13 15:49:50.880 -06:00 [Debug] [2017-06-13T21:49:50.8801563Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=AuthenticationController.Dispose
2017-06-13 15:49:50.880 -06:00 [Debug] [2017-06-13T21:49:50.8801563Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=3495821d-f3d0-43a3-8f73-719ef3bb6a91, Operation=AuthenticationController.Dispose
2017-06-13 15:49:50.880 -06:00 [Debug] HTTP Response
{
  "StatusCode": 200,
  "Headers": {
    "Content-Type": [
      "text/html; charset=utf-8"
    ],
    "Server": [
      "Microsoft-IIS/8.5"
    ],
    "Cache-Control": [
      "no-store, no-cache, max-age=0, private"
    ],
    "Pragma": [
      "no-cache"
    ],
    "X-Content-Type-Options": [
      "nosniff"
    ],
    "X-Frame-Options": [
      "SAMEORIGIN"
    ],
    "Content-Security-Policy": [
      "default-src 'self'; script-src 'self' https://www.google-analytics.com; style-src 'self' 'unsafe-inline' ; img-src *;  report-uri https://<ourUrl>/Identity/csp/report"
    ],
    "X-Content-Security-Policy": [
      "default-src 'self'; script-src 'self' https://www.google-analytics.com; style-src 'self' 'unsafe-inline' ; img-src *;  report-uri https://<ourUrl>/Identity/csp/report"
    ],
    "Content-Length": [
      "3513"
    ]
  },
  "Body": "<removed to keep text shorter>"
}
2017-06-13 15:49:51.037 -06:00 [Debug] HTTP Request
{
  "Method": "GET",
  "Url": "https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob%3A%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB",
  "Headers": {
    "Connection": [
      "Keep-Alive"
    ],
    "Accept": [
      "image/gif, image/jpeg, image/pjpeg, application/x-ms-application, application/xaml+xml, application/x-ms-xbap, */*"
    ],
    "Accept-Encoding": [
      "gzip, deflate"
    ],
    "Accept-Language": [
      "en-US"
    ],
    "Host": [
      "<ourUrl>"
    ],
    "User-Agent": [
      "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)"
    ],
    "UA-CPU": [
      "AMD64"
    ]
  },
  "Body": ""
}
2017-06-13 15:49:51.037 -06:00 [Debug] [2017-06-13T21:49:51.0371496Z] Request received, Method=GET, Url=https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB, Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB'
2017-06-13 15:49:51.037 -06:00 [Debug] [2017-06-13T21:49:51.0371496Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=DependencyScopeHandler.SendAsync
2017-06-13 15:49:51.037 -06:00 [Debug] [2017-06-13T21:49:51.0371496Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=PassiveAuthenticationMessageHandler.SendAsync
2017-06-13 15:49:51.037 -06:00 [Debug] [2017-06-13T21:49:51.0371496Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Route='controller:AuthorizeEndpoint,action:Get'', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:51.037 -06:00 [Debug] [2017-06-13T21:49:51.0371496Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='AuthorizeEndpoint', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:51.038 -06:00 [Debug] [2017-06-13T21:49:51.0371496Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:51.038 -06:00 [Debug] [2017-06-13T21:49:51.0381491Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:51.051 -06:00 [Debug] [2017-06-13T21:49:51.0501537Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='IdentityServer3.Core.Endpoints.AuthorizeEndpointController', Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:51.051 -06:00 [Debug] [2017-06-13T21:49:51.0511534Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='IdentityServer3.Core.Endpoints.AuthorizeEndpointController', Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:51.051 -06:00 [Debug] [2017-06-13T21:49:51.0511534Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=AuthorizeEndpointController.ExecuteAsync
2017-06-13 15:49:51.051 -06:00 [Debug] [2017-06-13T21:49:51.0511534Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:51.051 -06:00 [Debug] [2017-06-13T21:49:51.0511534Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Selected action 'Get(HttpRequestMessage request)'', Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:51.051 -06:00 [Debug] [2017-06-13T21:49:51.0511534Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0511534Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='The authentication filter did not encounter an error or set a principal.', Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=Begin, Category='System.Web.Http.ModelBinding', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=Begin, Category='System.Web.Http.ModelBinding', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Binding parameter 'request'', Operation=HttpRequestParameterBinding.ExecuteBindingAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=End, Category='System.Web.Http.ModelBinding', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Parameter 'request' bound to the value 'Method: GET, RequestUri: 'https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Connection: Keep-Alive
  Accept: image/gif
  Accept: image/jpeg
  Accept: image/pjpeg
  Accept: application/x-ms-application
  Accept: application/xaml+xml
  Accept: application/x-ms-xbap
  Accept: */*
  Accept-Encoding: gzip
  Accept-Encoding: deflate
  Accept-Language: en-US
  Host: <ourUrl>
  User-Agent: Mozilla/4.0
  User-Agent: (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)
  UA-CPU: AMD64
}'', Operation=HttpRequestParameterBinding.ExecuteBindingAsync
2017-06-13 15:49:51.052 -06:00 [Debug] [2017-06-13T21:49:51.0521538Z] Level=Info, Kind=End, Category='System.Web.Http.ModelBinding', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Model state is valid. Values: request=Method: GET, RequestUri: 'https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Connection: Keep-Alive
  Accept: image/gif
  Accept: image/jpeg
  Accept: image/pjpeg
  Accept: application/x-ms-application
  Accept: application/xaml+xml
  Accept: application/x-ms-xbap
  Accept: */*
  Accept-Encoding: gzip
  Accept-Encoding: deflate
  Accept-Language: en-US
  Host: <ourUrl>
  User-Agent: Mozilla/4.0
  User-Agent: (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)
  UA-CPU: AMD64
}', Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:51.053 -06:00 [Debug] [2017-06-13T21:49:51.0531538Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Action filter for 'Get(HttpRequestMessage request)'', Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.053 -06:00 [Debug] [2017-06-13T21:49:51.0531538Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.053 -06:00 [Debug] [2017-06-13T21:49:51.0531538Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Action filter for 'Get(HttpRequestMessage request)'', Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.053 -06:00 [Debug] [2017-06-13T21:49:51.0531538Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.053 -06:00 [Debug] [2017-06-13T21:49:51.0531538Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Action='Get(request=Method: GET, RequestUri: 'https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Connection: Keep-Alive
  Accept: image/gif
  Accept: image/jpeg
  Accept: image/pjpeg
  Accept: application/x-ms-application
  Accept: application/xaml+xml
  Accept: application/x-ms-xbap
  Accept: */*
  Accept-Encoding: gzip
  Accept-Encoding: deflate
  Accept-Language: en-US
  Host: <ourUrl>
  User-Agent: Mozilla/4.0
  User-Agent: (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)
  UA-CPU: AMD64
})'', Operation=ApiControllerActionInvoker.InvokeActionAsync
2017-06-13 15:49:51.053 -06:00 [Debug] [2017-06-13T21:49:51.0531538Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Invoking action 'Get(request=Method: GET, RequestUri: 'https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Connection: Keep-Alive
  Accept: image/gif
  Accept: image/jpeg
  Accept: image/pjpeg
  Accept: application/x-ms-application
  Accept: application/xaml+xml
  Accept: application/x-ms-xbap
  Accept: */*
  Accept-Encoding: gzip
  Accept-Encoding: deflate
  Accept-Language: en-US
  Host: <ourUrl>
  User-Agent: Mozilla/4.0
  User-Agent: (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)
  UA-CPU: AMD64
})'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:51.053 -06:00 [Information] Start authorize request
2017-06-13 15:49:51.053 -06:00 [Information] Start authorize request protocol validation
2017-06-13 15:49:51.071 -06:00 [Information] "Authorize request validation success"
 "{
  \"ClientId\": \"<removed>\",
  \"ClientName\": \"Sawtooth Software Account\",
  \"RedirectUri\": \"oob://desktopclient/sawtoothsoftware/staging\",
  \"AllowedRedirectUris\": [
    \"oob://desktopclient/sawtoothsoftware/staging\"
  ],
  \"SubjectId\": \"unknown\",
  \"ResponseType\": \"code id_token\",
  \"ResponseMode\": \"fragment\",
  \"Flow\": \"Hybrid\",
  \"RequestedScopes\": \"openid email contact_id license_api offline_access\",
  \"State\": \"uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q\",
  \"Nonce\": \"PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB\",
  \"Raw\": {
    \"client_id\": \"<removed>\",
    \"response_type\": \"code id_token\",
    \"scope\": \"openid email contact_id license_api offline_access\",
    \"redirect_uri\": \"oob://desktopclient/sawtoothsoftware/staging\",
    \"state\": \"uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q\",
    \"nonce\": \"PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB\"
  }
}"
2017-06-13 15:49:51.071 -06:00 [Information] User is not authenticated. Redirecting to login.
2017-06-13 15:49:51.071 -06:00 [Information] End authorize request
2017-06-13 15:49:51.071 -06:00 [Debug] [2017-06-13T21:49:51.0711535Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Action returned 'IdentityServer3.Core.Results.LoginResult'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:51.071 -06:00 [Information] Redirecting to login page
2017-06-13 15:49:51.071 -06:00 [Debug] Protecting message: "{\"ReturnUrl\":\"https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code%20id_token&scope=openid%20email%20contact_id%20license_api%20offline_access&redirect_uri=oob%3A%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB\",\"ClientId\":\"<removed>\",\"AcrValues\":[],\"Created\":636329873910501537}"
2017-06-13 15:49:51.072 -06:00 [Debug] [2017-06-13T21:49:51.0721537Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=ApiControllerActionInvoker.InvokeActionAsync, Status=302 (Redirect)
2017-06-13 15:49:51.072 -06:00 [Debug] [2017-06-13T21:49:51.0721537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Action filter for 'Get(HttpRequestMessage request)'', Operation=NoCacheAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:51.072 -06:00 [Debug] [2017-06-13T21:49:51.0721537Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=NoCacheAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:51.072 -06:00 [Debug] [2017-06-13T21:49:51.0721537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Action filter for 'Get(HttpRequestMessage request)'', Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:51.073 -06:00 [Debug] [2017-06-13T21:49:51.0721537Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=302 (Redirect)
2017-06-13 15:49:51.073 -06:00 [Debug] [2017-06-13T21:49:51.0731539Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=AuthorizeEndpointController.ExecuteAsync, Status=302 (Redirect)
2017-06-13 15:49:51.073 -06:00 [Debug] [2017-06-13T21:49:51.0731539Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=PassiveAuthenticationMessageHandler.SendAsync, Status=302 (Redirect)
2017-06-13 15:49:51.073 -06:00 [Debug] [2017-06-13T21:49:51.0731539Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=DependencyScopeHandler.SendAsync, Status=302 (Redirect)
2017-06-13 15:49:51.073 -06:00 [Debug] [2017-06-13T21:49:51.0731539Z] Sending response, Status=302 (Redirect), Method=GET, Url=https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code+id_token&scope=openid+email+contact_id+license_api+offline_access&redirect_uri=oob:%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB, Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Message='Content-type='none', content-length=unknown'
2017-06-13 15:49:51.073 -06:00 [Debug] [2017-06-13T21:49:51.0731539Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=AuthorizeEndpointController.Dispose
2017-06-13 15:49:51.073 -06:00 [Debug] [2017-06-13T21:49:51.0731539Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=ee85a5a4-c86c-4744-b0a2-9ec90b905f72, Operation=AuthorizeEndpointController.Dispose
2017-06-13 15:49:51.073 -06:00 [Debug] HTTP Response
{
  "StatusCode": 302,
  "Headers": {
    "Content-Type": [
      "text/html"
    ],
    "Server": [
      "Microsoft-IIS/8.5"
    ],
    "Set-Cookie": [
      "SA.SignInMessage.98fad141e5ef68b2cba3df092a46525b=5CrzxJUamfJug15f3wJ_Ow8BNDOsiBzptMW7LR7GBwW9j4a6vlmqyMvLnFcfXfqJbeGW7Jz6abg4hgckwfhOySgrhvBG3DTXvlPElmSvhfs-D5swTd4v-evPk-gIxyw6lNFtt82raxwSNebi93OE9Jfn0vdeCIFujhy9Hq_x9tGeVOKwRY-bpx17LdaZSx2vrVx7aNC5RoC3Af0wJ9-uXbAxAjmPBA0kUM2lfKwXL4DBNW1sYg6kJBNVjfHPqra20eFFkBh3crHgd0-VP4vOiGDwNK8EHRKY1R4RUDnl3aYNSoMoD6HnmYjCn4w-2kSaTNCAK0Qt5CvX6TrJRa3IUAwYGNPRz9OZ6me00ZKGe-rcVdGgOVNrcuFwmHH0Gk_xUnorpFxaA1UJl0SyebC6gDGlUugypHZr9Uh27L9VX_EtoCXLKcOPYDh5MxqjQ_fQMnudGP9ROrCdy5ruFfJy_3scea_359rz6HSRG_7HaPy9G96qX5e6_NYA0wwTm9xZOTCOjj30-t3YR_VbjhMwmlWcSnCn55R7JlZ3J0c6uM_ausv1WG8fzoaBH3RL2MW0k2UNihJzkFK_iDwD58GO46sI642a8uVna7ceyFw2MasCJc33xQKPMwaQwzBWaAc2KbTonV6UFRjcizLPraA6JVCzGPhgtaSLha6mFjpNC_suu4JOKjYLq5tiVL4Umut4JptnNMvv0R9NQX-eicHvrnuKVJqjdhNKVVhPn3QCjsbXrWfymWXTSz6XfFOL7E21; path=/Identity; secure; HttpOnly"
    ],
    "Location": [
      "https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b"
    ],
    "Content-Length": [
      "0"
    ]
  },
  "Body": ""
}
2017-06-13 15:49:51.142 -06:00 [Debug] HTTP Request
{
  "Method": "GET",
  "Url": "https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b",
  "Headers": {
    "Connection": [
      "Keep-Alive"
    ],
    "Accept": [
      "image/gif, image/jpeg, image/pjpeg, application/x-ms-application, application/xaml+xml, application/x-ms-xbap, */*"
    ],
    "Accept-Encoding": [
      "gzip, deflate"
    ],
    "Accept-Language": [
      "en-US"
    ],
    "Cookie": [
      "SA.SignInMessage.98fad141e5ef68b2cba3df092a46525b=5CrzxJUamfJug15f3wJ_Ow8BNDOsiBzptMW7LR7GBwW9j4a6vlmqyMvLnFcfXfqJbeGW7Jz6abg4hgckwfhOySgrhvBG3DTXvlPElmSvhfs-D5swTd4v-evPk-gIxyw6lNFtt82raxwSNebi93OE9Jfn0vdeCIFujhy9Hq_x9tGeVOKwRY-bpx17LdaZSx2vrVx7aNC5RoC3Af0wJ9-uXbAxAjmPBA0kUM2lfKwXL4DBNW1sYg6kJBNVjfHPqra20eFFkBh3crHgd0-VP4vOiGDwNK8EHRKY1R4RUDnl3aYNSoMoD6HnmYjCn4w-2kSaTNCAK0Qt5CvX6TrJRa3IUAwYGNPRz9OZ6me00ZKGe-rcVdGgOVNrcuFwmHH0Gk_xUnorpFxaA1UJl0SyebC6gDGlUugypHZr9Uh27L9VX_EtoCXLKcOPYDh5MxqjQ_fQMnudGP9ROrCdy5ruFfJy_3scea_359rz6HSRG_7HaPy9G96qX5e6_NYA0wwTm9xZOTCOjj30-t3YR_VbjhMwmlWcSnCn55R7JlZ3J0c6uM_ausv1WG8fzoaBH3RL2MW0k2UNihJzkFK_iDwD58GO46sI642a8uVna7ceyFw2MasCJc33xQKPMwaQwzBWaAc2KbTonV6UFRjcizLPraA6JVCzGPhgtaSLha6mFjpNC_suu4JOKjYLq5tiVL4Umut4JptnNMvv0R9NQX-eicHvrnuKVJqjdhNKVVhPn3QCjsbXrWfymWXTSz6XfFOL7E21"
    ],
    "Host": [
      "<ourUrl>"
    ],
    "User-Agent": [
      "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)"
    ],
    "UA-CPU": [
      "AMD64"
    ]
  },
  "Body": ""
}
2017-06-13 15:49:51.143 -06:00 [Debug] [2017-06-13T21:49:51.1431537Z] Request received, Method=GET, Url=https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b, Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b'
2017-06-13 15:49:51.143 -06:00 [Debug] [2017-06-13T21:49:51.1431537Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=DependencyScopeHandler.SendAsync
2017-06-13 15:49:51.143 -06:00 [Debug] [2017-06-13T21:49:51.1431537Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=PassiveAuthenticationMessageHandler.SendAsync
2017-06-13 15:49:51.143 -06:00 [Debug] [2017-06-13T21:49:51.1431537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Route='MS_SubRoutes:System.Web.Http.Routing.IHttpRouteData[]'', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:51.143 -06:00 [Debug] [2017-06-13T21:49:51.1431537Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Authentication', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:49:51.143 -06:00 [Debug] [2017-06-13T21:49:51.1431537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:51.143 -06:00 [Debug] [2017-06-13T21:49:51.1431537Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:51.145 -06:00 [Debug] [2017-06-13T21:49:51.1451542Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='IdentityServer3.Core.Endpoints.AuthenticationController', Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:49:51.145 -06:00 [Debug] [2017-06-13T21:49:51.1451542Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='IdentityServer3.Core.Endpoints.AuthenticationController', Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:49:51.145 -06:00 [Debug] [2017-06-13T21:49:51.1451542Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=AuthenticationController.ExecuteAsync
2017-06-13 15:49:51.145 -06:00 [Debug] [2017-06-13T21:49:51.1451542Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:51.145 -06:00 [Debug] [2017-06-13T21:49:51.1451542Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Selected action 'Login(String signin)'', Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='The authentication filter did not encounter an error or set a principal.', Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=Begin, Category='System.Web.Http.ModelBinding', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=Begin, Category='System.Web.Http.ModelBinding', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Binding parameter 'signin'', Operation=ModelBinderParameterBinding.ExecuteBindingAsync
2017-06-13 15:49:51.146 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=End, Category='System.Web.Http.ModelBinding', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Parameter 'signin' bound to the value '98fad141e5ef68b2cba3df092a46525b'', Operation=ModelBinderParameterBinding.ExecuteBindingAsync
2017-06-13 15:49:51.147 -06:00 [Debug] [2017-06-13T21:49:51.1461535Z] Level=Info, Kind=End, Category='System.Web.Http.ModelBinding', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Model state is valid. Values: signin=98fad141e5ef68b2cba3df092a46525b', Operation=HttpActionBinding.ExecuteBindingAsync
2017-06-13 15:49:51.147 -06:00 [Debug] [2017-06-13T21:49:51.1471523Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Action filter for 'Login(String signin)'', Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.147 -06:00 [Debug] [2017-06-13T21:49:51.1471523Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=SecurityHeadersAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.147 -06:00 [Debug] [2017-06-13T21:49:51.1471523Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Action filter for 'Login(String signin)'', Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.147 -06:00 [Debug] [2017-06-13T21:49:51.1471523Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=NoCacheAttribute.OnActionExecutingAsync
2017-06-13 15:49:51.147 -06:00 [Debug] [2017-06-13T21:49:51.1471523Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Action='Login(signin=98fad141e5ef68b2cba3df092a46525b)'', Operation=ApiControllerActionInvoker.InvokeActionAsync
2017-06-13 15:49:51.147 -06:00 [Debug] [2017-06-13T21:49:51.1471523Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Invoking action 'Login(signin=98fad141e5ef68b2cba3df092a46525b)'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:51.147 -06:00 [Information] Login page requested
2017-06-13 15:49:51.148 -06:00 [Debug] signin message passed to login: "{
  \"ReturnUrl\": \"https://<ourUrl>/Identity/connect/authorize?client_id=<removed>&response_type=code%20id_token&scope=openid%20email%20contact_id%20license_api%20offline_access&redirect_uri=oob%3A%2F%2Fdesktopclient%2Fsawtoothsoftware%2Fstaging&state=uV8ES8Bgeu4MZP55mGPaW84MzAfCl42GS23X0ks_ikSs4u6q&nonce=PJsn_NsuOhaOB4Uo2kRO62Vu_92r3DvAP3F5DKemeufxK_WB\",
  \"ClientId\": \"<removed>\",
  \"IdP\": null,
  \"Tenant\": null,
  \"LoginHint\": null,
  \"DisplayMode\": null,
  \"UiLocales\": null,
  \"AcrValues\": [],
  \"Created\": 636329873910501537
}"
2017-06-13 15:49:51.155 -06:00 [Information] rendering login page
2017-06-13 15:49:51.155 -06:00 [Debug] [2017-06-13T21:49:51.1551508Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Action returned 'IdentityServer3.Core.Results.LoginActionResult'', Operation=ReflectedHttpActionDescriptor.ExecuteAsync
2017-06-13 15:49:51.163 -06:00 [Debug] [2017-06-13T21:49:51.1631493Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=ApiControllerActionInvoker.InvokeActionAsync, Status=200 (OK)
2017-06-13 15:49:51.163 -06:00 [Debug] [2017-06-13T21:49:51.1631493Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Action filter for 'Login(String signin)'', Operation=NoCacheAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:51.163 -06:00 [Debug] [2017-06-13T21:49:51.1631493Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=NoCacheAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:51.164 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Action filter for 'Login(String signin)'', Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:51.164 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=SecurityHeadersAttribute.OnActionExecutedAsync, Status=200 (OK)
2017-06-13 15:49:51.164 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=AuthenticationController.ExecuteAsync, Status=200 (OK)
2017-06-13 15:49:51.164 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=PassiveAuthenticationMessageHandler.SendAsync, Status=200 (OK)
2017-06-13 15:49:51.164 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=DependencyScopeHandler.SendAsync, Status=200 (OK)
2017-06-13 15:49:51.164 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Sending response, Status=200 (OK), Method=GET, Url=https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b, Id=d6a6b292-5902-4440-8412-9f187f65799a, Message='Content-type='text/html; charset=utf-8', content-length=8819'
2017-06-13 15:49:51.164 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=AuthenticationController.Dispose
2017-06-13 15:49:51.165 -06:00 [Debug] [2017-06-13T21:49:51.1641492Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=d6a6b292-5902-4440-8412-9f187f65799a, Operation=AuthenticationController.Dispose
2017-06-13 15:49:51.165 -06:00 [Debug] HTTP Response
{
  "StatusCode": 200,
  "Headers": {
    "Content-Type": [
      "text/html; charset=utf-8"
    ],
    "Server": [
      "Microsoft-IIS/8.5"
    ],
    "Set-Cookie": [
      "SA.idsrv.xsrf=oH7jVikS9KV4l1uuGpdvMuKAfHYxxjOl3HKQOLWYwMYwXqAgJxDtpMtfI89BIySIHfxKokuHXpOeaJyd7tb0ShGEUowBCXiaWbQn5Olld5k; path=/Identity; secure; HttpOnly"
    ],
    "X-Frame-Options": [
      "SAMEORIGIN"
    ],
    "Cache-Control": [
      "no-store, no-cache, max-age=0, private"
    ],
    "Pragma": [
      "no-cache"
    ],
    "X-Content-Type-Options": [
      "nosniff"
    ],
    "Content-Security-Policy": [
      "default-src 'self'; script-src 'self' https://www.google-analytics.com; style-src 'self' 'unsafe-inline' ; img-src *;  report-uri https://<ourUrl>/Identity/csp/report"
    ],
    "X-Content-Security-Policy": [
      "default-src 'self'; script-src 'self' https://www.google-analytics.com; style-src 'self' 'unsafe-inline' ; img-src *;  report-uri https://<ourUrl>/Identity/csp/report"
    ],
    "Content-Length": [
      "8819"
    ]
  },
  "Body": "<removed to keep text shorter>"
}
2017-06-13 15:50:48.741 -06:00 [Information] Clearing tokens
2017-06-13 15:50:55.836 -06:00 [Debug] HTTP Request
{
  "Method": "POST",
  "Url": "https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b",
  "Headers": {
    "Cache-Control": [
      "no-cache"
    ],
    "Connection": [
      "Keep-Alive"
    ],
    "Content-Length": [
      "175"
    ],
    "Content-Type": [
      "application/x-www-form-urlencoded"
    ],
    "Accept": [
      "image/gif, image/jpeg, image/pjpeg, application/x-ms-application, application/xaml+xml, application/x-ms-xbap, */*"
    ],
    "Accept-Encoding": [
      "gzip, deflate"
    ],
    "Accept-Language": [
      "en-US"
    ],
    "Cookie": [
      "SA.SignInMessage.98fad141e5ef68b2cba3df092a46525b=5CrzxJUamfJug15f3wJ_Ow8BNDOsiBzptMW7LR7GBwW9j4a6vlmqyMvLnFcfXfqJbeGW7Jz6abg4hgckwfhOySgrhvBG3DTXvlPElmSvhfs-D5swTd4v-evPk-gIxyw6lNFtt82raxwSNebi93OE9Jfn0vdeCIFujhy9Hq_x9tGeVOKwRY-bpx17LdaZSx2vrVx7aNC5RoC3Af0wJ9-uXbAxAjmPBA0kUM2lfKwXL4DBNW1sYg6kJBNVjfHPqra20eFFkBh3crHgd0-VP4vOiGDwNK8EHRKY1R4RUDnl3aYNSoMoD6HnmYjCn4w-2kSaTNCAK0Qt5CvX6TrJRa3IUAwYGNPRz9OZ6me00ZKGe-rcVdGgOVNrcuFwmHH0Gk_xUnorpFxaA1UJl0SyebC6gDGlUugypHZr9Uh27L9VX_EtoCXLKcOPYDh5MxqjQ_fQMnudGP9ROrCdy5ruFfJy_3scea_359rz6HSRG_7HaPy9G96qX5e6_NYA0wwTm9xZOTCOjj30-t3YR_VbjhMwmlWcSnCn55R7JlZ3J0c6uM_ausv1WG8fzoaBH3RL2MW0k2UNihJzkFK_iDwD58GO46sI642a8uVna7ceyFw2MasCJc33xQKPMwaQwzBWaAc2KbTonV6UFRjcizLPraA6JVCzGPhgtaSLha6mFjpNC_suu4JOKjYLq5tiVL4Umut4JptnNMvv0R9NQX-eicHvrnuKVJqjdhNKVVhPn3QCjsbXrWfymWXTSz6XfFOL7E21; __RequestVerificationToken=19hjzSK6y59qIgMZ04iwYy1DbAA65zNdF1uCh4heVzGW6vu4SZMJiKreGWkVgR-W0Ye2XsUZrTjousWGJ0di99hQA-T8jEBoNgQnV42QIUY1"
    ],
    "Host": [
      "<ourUrl>"
    ],
    "Referer": [
      "https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b"
    ],
    "User-Agent": [
      "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 10.0; Win64; x64; Trident/7.0; .NET4.0C; .NET4.0E; .NET CLR 2.0.50727; .NET CLR 3.0.30729; .NET CLR 3.5.30729)"
    ],
    "UA-CPU": [
      "AMD64"
    ]
  },
  "Body": "idsrv.xsrf=m2nGCSsOdu4l-eRkRRYwW-lT-cgBMzN1Nk9cuW_y_6FvaOrZ6Hza8GDNB9C9v8cRJhcxGMeCrRH7yzmymrbO6paNxYZgdzO-YbaKQ6XRbsg&username=adam@sawtoothsoftware.com&password=<removed>"
}
2017-06-13 15:50:55.837 -06:00 [Debug] [2017-06-13T21:50:55.8361531Z] Request received, Method=POST, Url=https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b, Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b'
2017-06-13 15:50:55.837 -06:00 [Debug] [2017-06-13T21:50:55.8371533Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=DependencyScopeHandler.SendAsync
2017-06-13 15:50:55.837 -06:00 [Debug] [2017-06-13T21:50:55.8371533Z] Level=Info, Kind=Begin, Category='System.Web.Http.MessageHandlers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=PassiveAuthenticationMessageHandler.SendAsync
2017-06-13 15:50:55.837 -06:00 [Debug] [2017-06-13T21:50:55.8371533Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='Route='MS_SubRoutes:System.Web.Http.Routing.IHttpRouteData[]'', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:50:55.837 -06:00 [Debug] [2017-06-13T21:50:55.8371533Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='Authentication', Operation=DefaultHttpControllerSelector.SelectController
2017-06-13 15:50:55.837 -06:00 [Debug] [2017-06-13T21:50:55.8371533Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:50:55.837 -06:00 [Debug] [2017-06-13T21:50:55.8371533Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:50:55.839 -06:00 [Debug] [2017-06-13T21:50:55.8391539Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='IdentityServer3.Core.Endpoints.AuthenticationController', Operation=DefaultHttpControllerActivator.Create
2017-06-13 15:50:55.839 -06:00 [Debug] [2017-06-13T21:50:55.8391539Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='IdentityServer3.Core.Endpoints.AuthenticationController', Operation=HttpControllerDescriptor.CreateController
2017-06-13 15:50:55.839 -06:00 [Debug] [2017-06-13T21:50:55.8391539Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=AuthenticationController.ExecuteAsync
2017-06-13 15:50:55.839 -06:00 [Debug] [2017-06-13T21:50:55.8391539Z] Level=Info, Kind=Begin, Category='System.Web.Http.Action', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=End, Category='System.Web.Http.Action', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='Selected action 'LoginLocal(String signin, LoginCredentials model)'', Operation=ApiControllerActionSelector.SelectAction
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='The authentication filter did not encounter an error or set a principal.', Operation=HostAuthenticationAttribute.AuthenticateAsync
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=HostAuthenticationAttribute.ChallengeAsync
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=PreventUnsupportedRequestMediaTypesAttribute.OnAuthorizationAsync
2017-06-13 15:50:55.840 -06:00 [Debug] [2017-06-13T21:50:55.8401540Z] Level=Info, Kind=Begin, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=ValidateAntiForgeryTokenAttribute.OnAuthorizationAsync
2017-06-13 15:50:55.841 -06:00 [Error] AntiForgery validation failed -- returning error page
2017-06-13 15:50:55.844 -06:00 [Debug] [2017-06-13T21:50:55.8441512Z] Level=Info, Kind=End, Category='System.Web.Http.Filters', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=ValidateAntiForgeryTokenAttribute.OnAuthorizationAsync, Status=200 (OK)
2017-06-13 15:50:55.844 -06:00 [Debug] [2017-06-13T21:50:55.8441512Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=AuthenticationController.ExecuteAsync, Status=200 (OK)
2017-06-13 15:50:55.844 -06:00 [Debug] [2017-06-13T21:50:55.8441512Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=PassiveAuthenticationMessageHandler.SendAsync, Status=200 (OK)
2017-06-13 15:50:55.844 -06:00 [Debug] [2017-06-13T21:50:55.8441512Z] Level=Info, Kind=End, Category='System.Web.Http.MessageHandlers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=DependencyScopeHandler.SendAsync, Status=200 (OK)
2017-06-13 15:50:55.845 -06:00 [Debug] [2017-06-13T21:50:55.8441512Z] Sending response, Status=200 (OK), Method=POST, Url=https://<ourUrl>/Identity/login?signin=98fad141e5ef68b2cba3df092a46525b, Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Message='Content-type='text/html; charset=utf-8', content-length=4081'
2017-06-13 15:50:55.845 -06:00 [Debug] [2017-06-13T21:50:55.8451532Z] Level=Info, Kind=Begin, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=AuthenticationController.Dispose
2017-06-13 15:50:55.845 -06:00 [Debug] [2017-06-13T21:50:55.8451532Z] Level=Info, Kind=End, Category='System.Web.Http.Controllers', Id=fefdef4d-9fdc-4a8e-9366-980cb604460d, Operation=AuthenticationController.Dispose
2017-06-13 15:50:55.845 -06:00 [Debug] HTTP Response
{
  "StatusCode": 200,
  "Headers": {
    "Content-Type": [
      "text/html; charset=utf-8"
    ],
    "Server": [
      "Microsoft-IIS/8.5"
    ],
    "Set-Cookie": [
      "SA.idsrv.xsrf=YAcoSnBfPH9gkJlFu0IVxH8cKu7IeEZ5QYNfLHi-E0sq0UdP9ig-vW9kRqR3OHZNpala95G_b46yAdlR-pGDtbW2wjkqrf9rI619XTNHAU0; path=/Identity; secure; HttpOnly"
    ],
    "Content-Length": [
      "4081"
    ]
  },
  "Body": "<!DOCTYPE html>\r\n<html>\r\n<head>\r\n    <meta charset=\"utf-8\" />\r\n    <meta name=\"viewport\" content=\"width=device-width, initial-scale=1.0, user-scalable=no\">\r\n    <meta http-equiv=\"X-UA-Compatible\" content=\"IE=edge\">\r\n    <title>Error - Sawtooth Software</title>\r\n    <link href=\"/favicon.ico\" rel=\"shortcut icon\" type=\"image/x-icon\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"57x57\" href=\"/apple-touch-icon-57x57.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"60x60\" href=\"/apple-touch-icon-60x60.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"72x72\" href=\"/apple-touch-icon-72x72.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"76x76\" href=\"/apple-touch-icon-76x76.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"114x114\" href=\"/apple-touch-icon-114x114.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"120x120\" href=\"/apple-touch-icon-120x120.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"144x144\" href=\"/apple-touch-icon-144x144.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"152x152\" href=\"/apple-touch-icon-152x152.png\">\r\n    <link rel=\"apple-touch-icon\" sizes=\"180x180\" href=\"/apple-touch-icon-180x180.png\">\r\n    <link rel=\"icon\" type=\"image/png\" href=\"/favicon-32x32.png\" sizes=\"32x32\">\r\n    <link rel=\"icon\" type=\"image/png\" href=\"/android-chrome-192x192.png\" sizes=\"192x192\">\r\n    <link rel=\"icon\" type=\"image/png\" href=\"/favicon-96x96.png\" sizes=\"96x96\">\r\n    <link rel=\"icon\" type=\"image/png\" href=\"/favicon-16x16.png\" sizes=\"16x16\">\r\n    <link rel=\"manifest\" href=\"/manifest.json\">\r\n    <link rel=\"mask-icon\" href=\"/safari-pinned-tab.svg\" color=\"#0c3451\">\r\n    <meta name=\"apple-mobile-web-app-title\" content=\"Sawtooth Software Account\">\r\n    <meta name=\"application-name\" content=\"Sawtooth Software Account\">\r\n    <meta name=\"msapplication-TileColor\" content=\"#0c3451\">\r\n    <meta name=\"msapplication-TileImage\" content=\"/mstile-144x144.png\">\r\n    <meta name=\"theme-color\" content=\"#0c3451\">\r\n    <meta name=\"mobile-web-app-capable\" content=\"yes\">\r\n    <link href=\"/Content/css?v=9gDMeiypeiw4JuaBCp_vecfMX0JN7Qy8wAOyVybdUBE1\" rel=\"stylesheet\"/>\r\n\r\n</head>\r\n<body>\r\n    <div class=\"wrapper\">\r\n        <header id=\"Header\" class=\"navbar navbar-inverse sawtooth-header\">\r\n            <div class=\"container\">\r\n                <div class=\"navbar-header\">\r\n                        <a href=\"/\"><span class=\"logo\"></span></a>\r\n                </div>\r\n                <div id=\"LogOutContainer\">\r\n                    \r\n                </div>\r\n            </div>\r\n        </header>\r\n        <div id=\"Body\" class=\"container\">\r\n            \r\n            \r\n\r\n\r\n<div class=\"text-center\">\r\n    <div class=\"page-title\"></div>\r\n    <div class=\"text-left\">\r\n        <strong>Error:</strong>\r\n        <span id=\"errorMessage\" class=\"field-validation-error\">There was an unexpected error</span>\r\n        <span id=\"cookiesRequired\">\r\n            This website requires cookies.  It appears your web browser has cookies disabled. Please enable cookies to continue.\r\n        </span>\r\n        <noscript>\r\n            <div class=\"missingBrowserFunctionality\">\r\n                This website requires JavaScript.  We have detected that your web browser does not support JavaScript or JavaScript is disabled.\r\n                Please switch to a web browser that supports JavaScript or <a href=\"http://www.enable-javascript.com/\" target=\"enable_javascript\">enable JavaScript</a> in your web browser's\r\n                settings.\r\n            </div>\r\n        </noscript>\r\n    </div>\r\n</div>\r\n\r\n\r\n        </div>\r\n        <div class=\"push\"></div>\r\n    </div>\r\n    <footer id=\"Footer\" class=\"text-center copyright\">\r\n        &copy; 2017 Sawtooth Software, Inc. All rights reserved. | <a target=\"_blank\" href=\"http://www.sawtoothsoftware.com/about-us/contact-us\">Contact Us</a>\r\n    </footer>\r\n\r\n    <script src=\"/bundles/jquery?v=auORHXBod1U53q61ZPzRHTWiELheuE4ej_ikh5HOv0E1\"></script>\r\n<script src=\"/bundles/bootstrap?v=-g7cxTWQV6ve_iRyKtg7LoBytQltgj_w8zTNeaLaBc41\"></script>\r\n\r\n        \r\n    <script src=\"/bundles/CookieCheck?v=7tpsM6oPesVZIutrv2WUlPVCD-mRE-el7n3eknXiIOA1\"></script>\r\n\r\n\r\n</body>\r\n</html>\r\n"
}
brockallen commented 7 years ago

So in short, .net 4.7 breaks something related to the anti-forgery token from working in IdSvr3?

AdamDotNet commented 7 years ago

Yes, it seems anti forgery token is broken in .net 4.7; specifically, when using hybrid flow with the IE browser control in wpf. Surprisingly, implicit flow in a full browser for website login worked.

brockallen commented 7 years ago

Looking at the log, I really think this will end up being an issue for Microsoft. In short, the POST to the login endpoint is not sending the .xsrf cookie for some reason (but it is sending the .SignInMessage oddly enough). It's almost as if we need logs from the embedded IE to know why.

AdamDotNet commented 7 years ago

Just FYI, I've been trying to reproduce this some more.

When I tried enacting the hybrid flow using HttpClient instead of a web browser, I noticed that the server simply wasn't sending the cookie, not that IE embedded wasn't passing it back up to the server.

Request /connect/authorize Response 302 + SignInMessage cookie Request /login Response 200 + login HTML (here's where it should also add the xsrf cookie, but isn't) Request to sign in, anti forgery token failure, etc.

So I tried to make a simpler identity server to see if it really is just .Net 4.7 on the server breaking it. I took the "WebHost (minimal)" sample and added a few of my app specific configs and... it just works!

So there are interaction effects with my app compared to a simple app. I'm guessing ideal deployment is the Identity Server bit is its own application in IIS? My company's SSO solution includes a web dashboard, and we ended up making a single MVC app with Identity server and the website as one web application. Part of that was maintaining the same host URL (so account.company.com serves both a web UI and hosts the identity solution at account.company.com/Identity, versus account.company.com and identity.company.com or something like that; I now realize though that it should be possible to do that by putting the identity application inside the main app's virtual directory/application, right?). Another part was sharing Razor layout to ensure consistency with the web portal UI and the sign on page, done by implementing a ViewService and basically pointing it to rendered Razor bytes returned from manually calling the ViewEngine. Have I committed a horrible sin against your tool by doing things this way?

It's a little hard to rip apart my web UI and identity server to see if things start working again, because of the coupled view service, but it's something I'd like to try and find out. .Net 4.7 is clearly part of it, but perhaps my app needs a refactor all the same. The plot thickens.

AdamDotNet commented 7 years ago

I have a complete explanation of the problem now.

We have requirements that include showing a different sign in page when signing in as a desktop client versus a web client. The desktop page has both the sign in fields and the registration fields; the user clicks on "already have an account" or "register" in order to sign in or create an account respectively.

Well, the register part has its own anti forgery token. The cookie name is RequestVerificationToken, spawned by using @Html.AntiForgeryToken() in the razor file. When RequestVerificationToken is present, SA.idsrv.xsrf is not. When I remove my AntiForgeryToken, then SA.idsrv.xsrf will be present.

Because the web client sign in page uses different razor that doesn't include the register part, it just works.

All explained.

I can probably close this question soon, unless you have any suggestions. The last basic question: why does Asp.Net 4.7 choose to only send one anti forgery token header, even though the names do not collide, versus simply sending both like it did in Asp.Net 4.6.x?

The answer could be suck it up, and change my flow ensuring only one anti forgery token is present always; or remove my anti forgery token completely (seems bad); or find out where Asp.Net 4.7 is messing with my cookies.

brockallen commented 7 years ago

Hmm, not clue why the Microsoft AF token dynamically shows up. Our implementation is our own and unrelated to Microsoft's. To really understand, I'd likely need to debug thru to the level you have...

AdamDotNet commented 7 years ago

Now that I know the cause, I should be able to produce a simple app I can share with you to reproduce it. But I'll have to work on it on Monday.

AdamDotNet commented 7 years ago

Code to reproduce the issue has been created.

  1. I forked https://github.com/IdentityServer/IdentityServer3 to https://github.com/AdamDotNet/IdentityServer3
  2. I deleted the sample projects for self host and web host, along with their configuration.
  3. I added the project MinimalServer, which has just enough configuration to show the issue.
  4. I added the project MinimalServer.Tests, which has 2 tests in it for detecting if the Antiforgery Tokens exist or not.

Ensure MinimalServer is running in IIS Express, then run the unit tests. Only one test can pass at a time because either it has the MVC token but not the idsrv token, or it has the idsrv token because the MVC token is not present. You can toggle the MVC token being present by commenting out this line:

https://github.com/AdamDotNet/IdentityServer3/blob/6fa3d74047cfc73acdea36797934914addcc60a6/source/MinimalServer/Views/IdentityServer/Login.cshtml#L12

AdamDotNet commented 7 years ago

Hey Brock, first I just want to say thank you for the time you have spent on this so far and thank you for IdentityServer3 period!

This scenario probably seems pretty odd, but that's how we've been running for quite some time now. I've tried stepping through it myself and all I can tell is that by the time AuthenticationController.Login finishes, the IOwinContext.Response.Cookies.Headers has the right Set-Cookie for idsrv.xsrf and then it never reaches clients. System.Web must be eating it... I've used reflection where I could to try and understand System.Web doing cookies, and even tried forcing IdentityServer3 to use System.Web to wire up

https://github.com/aspnet/AspNetKatana/blob/dev/src/Microsoft.Owin.Host.SystemWeb/SystemWebCookieManager.cs

But that was to no avail.

Have you had any time to look at this? Have you had any more ideas or luck than me? I might have to start thinking of work arounds, which up to this point has been avoid .Net 4.7... but I think I can come up with more if we really feel like making it work on 4.7 and there is no solution in this layer.

leastprivilege commented 7 years ago

Have you considered updating to IdentityServer4 ?

brockallen commented 7 years ago

Yea, prolly something changed in the bowels of System.Web under this release. Wonderful.

AdamDotNet commented 7 years ago

@leastprivilege That might indeed be a good solution, but it would be a lot of rewrite on my end to get to Asp.Net Core and friends (but ultimately that would probably be a good thing). Is there an eminent "end of life" or "deprecation" for IdentityServer3 I should be concerned about? As long as I can come up with roughly the same user experience, I think avoiding having an MVC anti forgery token on the same page as your token is probably a small enough change that I can make it work. But if v3 is dead, I have a compelling argument to give to my boss.

leastprivilege commented 7 years ago

Well - all I am saying is that any new feature development will go into 4. We are just a two person team really.

leastprivilege commented 7 years ago

..and your problem would also go away (plus other unforeseen things in the future). Katana is not really the ASP.NET teams's main focus anymore.

AdamDotNet commented 7 years ago

Yeah I totally understand and can sympathize that it's just you two and it's one of your older versions that doesn't run on Microsoft's currently developed platform. I'll have to consult my team!