K
Q

Question

Access denied on Logout after restarting pod

8/9/2019

We have microservice with identity server 4. When user login to the app, and we restart pod with this microservice, then somehow token is still valid (user can browse app) but when he click logout then there is call to endsession which removes the token and redirection to logout page (but since there is no token we get access denied )

2019-08-14 08:19:57.5514|DEBUG|||||MyNamespace.UserManagement.Api.Program||init main |!LOGEND!
2019-08-14 08:19:58.5769|INFO|||||MyNamespace.Common.Core.Rpc.Client.RpcClientServiceCollectionExtensions|UserManagement.Api|Rpc Client:PermissionsServiceClient is connecting to usermanagement-worker:9090 |!LOGEND!
2019-08-14 08:19:58.7928|INFO|||||MyNamespace.Common.Core.Rpc.Client.RpcClientServiceCollectionExtensions|UserManagement.Api|Rpc Client:NotificationServiceClient is connecting to notification-worker:9090 |!LOGEND!
2019-08-14 08:19:58.7928|INFO|||||MyNamespace.Common.Core.Rpc.Client.RpcClientServiceCollectionExtensions|UserManagement.Api|Rpc Client:ContentFileServiceClient is connecting to content-worker:9090 |!LOGEND!
2019-08-14 08:19:59.0045|WARN|||||Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager|UserManagement.Api|No XML encryptor configured. Key {d4445b6b-a8ae-47b4-bd08-2ff446b40755} may be persisted to storage in unencrypted form. |!LOGEND!
2019-08-14 08:19:59.0865|INFO|||||IdentityServer4.Startup|UserManagement.Api|You are using the in-memory version of the persisted grant store. This will store consent decisions, authorization codes, refresh and reference tokens in memory only. If you are using any of those features in production, you want to switch to a different store implementation. |!LOGEND!
2019-08-14 08:19:59.0986|INFO|||||IdentityServer4.Startup|UserManagement.Api|Using the default authentication scheme Identity.Application for IdentityServer |!LOGEND!
2019-08-14 08:19:59.0986|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Using Identity.Application as default ASP.NET Core scheme for authentication |!LOGEND!
2019-08-14 08:19:59.0986|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Using Identity.External as default ASP.NET Core scheme for sign-in |!LOGEND!
2019-08-14 08:19:59.0986|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Using Identity.External as default ASP.NET Core scheme for sign-out |!LOGEND!
2019-08-14 08:19:59.0986|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Using Identity.Application as default ASP.NET Core scheme for challenge |!LOGEND!
2019-08-14 08:19:59.0986|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Using Identity.Application as default ASP.NET Core scheme for forbid |!LOGEND!
2019-08-14 08:20:02.4042|INFO|||||MyNamespace.UserManagement.Domain.UserManagementDataContext|UserManagement.Api|Seeding data for  |!LOGEND!
2019-08-14 08:20:02.8778|WARN|||||Microsoft.EntityFrameworkCore.Query|UserManagement.Api|The Include operation for navigation '[rp].Permission' is unnecessary and was ignored because the navigation is not reachable in the final query results. See https://go.microsoft.com/fwlink/?linkid=850303 for more information. |!LOGEND!
2019-08-14 08:20:02.8778|WARN|||||Microsoft.EntityFrameworkCore.Query|UserManagement.Api|The Include operation for navigation '[rp].Role' is unnecessary and was ignored because the navigation is not reachable in the final query results. See https://go.microsoft.com/fwlink/?linkid=850303 for more information. |!LOGEND!
2019-08-14 08:20:03.1423|DEBUG|||||Jaeger.Configuration|UserManagement.Api|Using the UDP Sender to send spans to the agent. |!LOGEND!
Hosting environment: Production
Content root path: /app
Now listening on: http://[::]:80
Application started. Press Ctrl+C to shut down.
2019-08-14 08:20:19.3125|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:20:26.1147|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:20:32.2729|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Login Url: /Account/Login |!LOGEND!
2019-08-14 08:20:32.2729|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Login Return Url Parameter: ReturnUrl |!LOGEND!
2019-08-14 08:20:32.2729|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Logout Url: /Account/Logout |!LOGEND!
2019-08-14 08:20:32.2729|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|ConsentUrl Url: /consent |!LOGEND!
2019-08-14 08:20:32.2729|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Consent Return Url Parameter: returnUrl |!LOGEND!
2019-08-14 08:20:32.2729|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Error Url: /home/error |!LOGEND!
2019-08-14 08:20:32.2729|DEBUG|||||IdentityServer4.Startup|UserManagement.Api|Error Id Parameter: errorId |!LOGEND!
2019-08-14 08:20:39.2364|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:20:46.1140|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:20:56.1262|DEBUG|||||IdentityServer4.Hosting.EndpointRouter|UserManagement.Api|Request path /connect/authorize matched to endpoint type Authorize |!LOGEND!
2019-08-14 08:20:56.1423|DEBUG|||||IdentityServer4.Hosting.EndpointRouter|UserManagement.Api|Endpoint enabled: Authorize, successfully created handler: IdentityServer4.Endpoints.AuthorizeEndpoint |!LOGEND!
2019-08-14 08:20:56.1423|INFO|||||IdentityServer4.Hosting.IdentityServerMiddleware|UserManagement.Api|Invoking IdentityServer endpoint: IdentityServer4.Endpoints.AuthorizeEndpoint for /connect/authorize |!LOGEND!
2019-08-14 08:20:56.1461|DEBUG|||||IdentityServer4.Endpoints.AuthorizeEndpoint|UserManagement.Api|Start authorize request |!LOGEND!
2019-08-14 08:20:56.1563|DEBUG|||||IdentityServer4.Endpoints.AuthorizeEndpoint|UserManagement.Api|No user present in authorize request |!LOGEND!
2019-08-14 08:20:56.1606|DEBUG|||||IdentityServer4.Validation.AuthorizeRequestValidator|UserManagement.Api|Start authorize request protocol validation |!LOGEND!
2019-08-14 08:20:56.1783|DEBUG|||||IdentityServer4.Stores.ValidatingClientStore|UserManagement.Api|client configuration validation for client 9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed succeeded. |!LOGEND!
2019-08-14 08:20:56.2215|DEBUG|||||IdentityServer4.Validation.AuthorizeRequestValidator|UserManagement.Api|Calling into custom validator: IdentityServer4.Validation.DefaultCustomAuthorizeRequestValidator |!LOGEND!
2019-08-14 08:20:56.2215|INFO|||||IdentityServer4.Endpoints.AuthorizeEndpoint|UserManagement.Api|ValidatedAuthorizeRequest
{"ClientId":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed", "ClientName":"angularclient", "RedirectUri":"https:\/\/myUrl\/silent-renew.html", "AllowedRedirectUris":["https:\/\/myUrl\/#\/auth-callback?","https:\/\/myUrl\/silent-renew.html","http:\/\/localhost:4200\/#\/auth-callback?","https:\/\/localhost:4200\/silent-renew.html"], "SubjectId":"anonymous", "ResponseType":"id_token token", "ResponseMode":"fragment", "GrantType":"implicit", "RequestedScopes":"openid profile Apis", "State":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6", "UiLocales":"en", "Nonce":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6", "PromptMode":"none", "LoginHint":"myemail@domain.com", "Raw":{"response_type":"id_token token","client_id":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed","state":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6","redirect_uri":"https:\/\/myUrl\/silent-renew.html","scope":"openid profile Apis","nonce":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6","prompt":"none","ui_locales":"en","login_hint":"myemail@domain.com"}} |!LOGEND!
2019-08-14 08:20:56.2725|INFO|||||IdentityServer4.ResponseHandling.AuthorizeInteractionResponseGenerator|UserManagement.Api|Showing error: prompt=none was requested but user is not authenticated |!LOGEND!
2019-08-14 08:20:56.2750|INFO|||||IdentityServer4.Endpoints.AuthorizeEndpoint|UserManagement.Api|{"ClientId":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed", "ClientName":"angularclient", "RedirectUri":"https:\/\/myUrl\/silent-renew.html", "AllowedRedirectUris":["https:\/\/myUrl\/#\/auth-callback?","https:\/\/myUrl\/silent-renew.html","http:\/\/localhost:4200\/#\/auth-callback?","https:\/\/localhost:4200\/silent-renew.html"], "SubjectId":"anonymous", "ResponseType":"id_token token", "ResponseMode":"fragment", "GrantType":"implicit", "RequestedScopes":"openid profile Apis", "State":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6", "UiLocales":"en", "Nonce":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6", "PromptMode":"none", "LoginHint":"myemail@domain.com", "Raw":{"response_type":"id_token token","client_id":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed","state":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6","redirect_uri":"https:\/\/myUrl\/silent-renew.html","scope":"openid profile Apis","nonce":"MaWNo5cO47XXFUFMrUW0xNv7F3sMpfr3ngFOJpr6","prompt":"none","ui_locales":"en","login_hint":"myemail@domain.com"}} |!LOGEND!
2019-08-14 08:20:56.2896|INFO|||||IdentityServer4.Events.DefaultEventService|UserManagement.Api|{"ClientId":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed", "ClientName":"angularclient", "RedirectUri":"https:\/\/myUrl\/silent-renew.html", "Endpoint":"Authorize", "Scopes":"openid profile Apis", "GrantType":"implicit", "Error":"login_required", "Category":"Token", "Name":"Token Issued Failure", "EventType":"Failure", "Id":2001, "ActivityId":"0HLP0I0V87B7O:00000005", "TimeStamp":"2019-08-14T08:20:56Z", "ProcessId":1, "LocalIpAddress":"::ffff:127.0.0.1:80", "RemoteIpAddress":"10.123.88.10"} |!LOGEND!
2019-08-14 08:20:59.2361|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:21:06.1138|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:21:09.5788|DEBUG|||||IdentityServer4.Hosting.EndpointRouter|UserManagement.Api|Request path /.well-known/openid-configuration/jwks matched to endpoint type Discovery |!LOGEND!
2019-08-14 08:21:09.5878|DEBUG|||||IdentityServer4.Hosting.EndpointRouter|UserManagement.Api|Endpoint enabled: Discovery, successfully created handler: IdentityServer4.Endpoints.DiscoveryKeyEndpoint |!LOGEND!
2019-08-14 08:21:09.5878|INFO|||||IdentityServer4.Hosting.IdentityServerMiddleware|UserManagement.Api|Invoking IdentityServer endpoint: IdentityServer4.Endpoints.DiscoveryKeyEndpoint for /.well-known/openid-configuration/jwks |!LOGEND!
2019-08-14 08:21:09.5912|DEBUG|||||IdentityServer4.Endpoints.DiscoveryKeyEndpoint|UserManagement.Api|Start key discovery request |!LOGEND!
2019-08-14 08:21:16.8870|DEBUG|||||IdentityServer4.Hosting.EndpointRouter|UserManagement.Api|Request path /connect/endsession matched to endpoint type Endsession |!LOGEND!
2019-08-14 08:21:16.8925|DEBUG|||||IdentityServer4.Hosting.EndpointRouter|UserManagement.Api|Endpoint enabled: Endsession, successfully created handler: IdentityServer4.Endpoints.EndSessionEndpoint |!LOGEND!
2019-08-14 08:21:16.8925|INFO|||||IdentityServer4.Hosting.IdentityServerMiddleware|UserManagement.Api|Invoking IdentityServer endpoint: IdentityServer4.Endpoints.EndSessionEndpoint for /connect/endsession |!LOGEND!
2019-08-14 08:21:16.8970|DEBUG|||||IdentityServer4.Endpoints.EndSessionEndpoint|UserManagement.Api|Processing signout request for anonymous |!LOGEND!
2019-08-14 08:21:16.9025|DEBUG|||||IdentityServer4.Validation.EndSessionRequestValidator|UserManagement.Api|Start end session request validation |!LOGEND!
2019-08-14 08:21:16.9097|DEBUG|||||IdentityServer4.Validation.TokenValidator|UserManagement.Api|Start identity token validation |!LOGEND!
2019-08-14 08:21:16.9462|DEBUG|||||IdentityServer4.Stores.ValidatingClientStore|UserManagement.Api|client configuration validation for client 9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed succeeded. |!LOGEND!
2019-08-14 08:21:16.9462|DEBUG|||||IdentityServer4.Validation.TokenValidator|UserManagement.Api|Client found: 9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed / angularclient |!LOGEND!
2019-08-14 08:21:17.0891|DEBUG|||||IdentityServer4.Validation.TokenValidator|UserManagement.Api|Calling into custom token validator: IdentityServer4.Validation.DefaultCustomTokenValidator |!LOGEND!
2019-08-14 08:21:17.0899|DEBUG|||||IdentityServer4.Validation.TokenValidator|UserManagement.Api|Token validation success
{"ClientId":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed", "ClientName":"angularclient", "ValidateLifetime":false, "Claims":{"nbf":1565770492,"exp":1565772292,"iss":"https:\/\/myurl\/usermanagement","aud":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed","nonce":"HTd1yWr7DEeL1BAxRSDJsNb4JkOdjFSRt","iat":1565770492,"at_hash":"HgkgWuBFWj9MTUYnKdU9Gw","sid":"534fb69c314ab146dc699f34d0f64e47","sub":"8d961fe9-cdcb-4563-abc2-e503d2794e1f","auth_time":1565770491,"idp":"ActiveDirectory","amr":"external"}} |!LOGEND!
2019-08-14 08:21:17.0963|INFO|||||IdentityServer4.Validation.EndSessionRequestValidator|UserManagement.Api|End session request validation failure: Invalid post logout URI
{"ClientId":"9e7b8d6a-ac6c-4f68-94eb-dd8ef7d17eed", "ClientName":"angularclient", "SubjectId":"unknown", "Raw":{"id_token_hint":"eyJhbGciOiJSUzI1NiIsImtpZCI6IkI5QjUyOEY2OTAyMzhCOTNBQTkzM0MyNUMyNU","post_logout_redirect_uri":"https:\/\/myUrl\/#\/auth-callback?"}} |!LOGEND!
2019-08-14 08:21:17.0998|ERROR|||||IdentityServer4.Endpoints.EndSessionEndpoint|UserManagement.Api|Error processing end session request Invalid request |!LOGEND!
2019-08-14 08:21:19.2363|DEBUG|3ddef511-e2d0-4a00-ac5e-69c0cf47e61c|HttpAPI|/Account/AccessDenied (GET)||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:21:26.1139|DEBUG|3ddef511-e2d0-4a00-ac5e-69c0cf47e61c|HttpAPI|/Account/AccessDenied (GET)||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:21:39.2363|DEBUG|3ddef511-e2d0-4a00-ac5e-69c0cf47e61c|HttpAPI|/Account/AccessDenied (GET)||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:21:46.1138|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!
2019-08-14 08:21:59.2363|DEBUG|||||OpenTracing.Contrib.NetCore.AspNetCore.AspNetCoreDiagnostics|UserManagement.Api|Ignoring request |!LOGEND!

and my startup

.AddSigningCertificates(certificatesSettings)
                .AddInMemoryIdentityResources(IdentityProviderConfig.IdentityResources)
                .AddInMemoryApiResources(IdentityProviderConfig.ApiResources)
                .AddInMemoryClients(IdentityProviderConfig.GetClients(identityConfig))
                .AddAspNetIdentity<ApplicationUser>()
                .AddProfileService<IdentityWithAdditionalClaimsProfileService>();

-- kosnkov

identityserver4

istio

kubernetes

1 Answer

8/14/2019

Since you're not properly persisting your persisted grants, signing credentials and data protection keys then you will get all sorts of odd behavior when you scale across multiple processes or restart an instance. You must address these considerations before deploying into this sort of environment.

I suspect in your example the cookie issued to the user is no longer valid as the data protection keys used to encrypt and sign said cookie will no longer exist.

See the following documentation:

Guidance from the identityserver4 authors: http://docs.identityserver.io/en/latest/topics/deployment.html
Deploying ASP.Net Core: https://docs.microsoft.com/en-us/aspnet/core/host-and-deploy/proxy-load-balancer?view=aspnetcore-2.2#scenarios-and-use-cases
ASP.NET Core Data Protection: https://docs.microsoft.com/en-us/aspnet/core/security/data-protection/introduction?view=aspnetcore-2.2

-- mackie

Source: StackOverflow

KQ

Access denied on Logout after restarting pod

Similar Questions

1 Answer

K
Q