Refresh_Token Timeout Resulting In Stuck Angular Client #1117

4 Answer(s)

• 

  0

  riley.trevillion created 3 years ago

  API / Identity Server Log

  ---

  I've removed some of the repeating successful token refresh lines to fit within forum text limit

  [23:27:53 INF] Request starting HTTP/2 OPTIONS [https://localhost:44362/connect/token](https://localhost:44362/connect/token) - -
  [23:27:53 INF] CORS policy execution successful.
  [23:27:53 INF] Request finished HTTP/2 OPTIONS [https://localhost:44362/connect/token](https://localhost:44362/connect/token) - - - 204 - - 0.2743ms
  [23:27:53 INF] Request starting HTTP/2 POST [https://localhost:44362/connect/token](https://localhost:44362/connect/token) application/x-www-form-urlencoded 160
  [23:27:53 INF] CORS policy execution successful.
  [23:27:53 INF] Successfully validated the token.
  [23:27:53 DBG] CORS request made for path: /connect/token from origin: [http://localhost:4200](http://localhost:4200)
  [23:27:53 DBG] CorsPolicyService allowed origin: [http://localhost:4200](http://localhost:4200)
  [23:27:53 INF] CORS policy execution successful.
  [23:27:53 DBG] Request path /connect/token matched to endpoint type Token
  [23:27:53 DBG] Endpoint enabled: Token, successfully created handler: IdentityServer4.Endpoints.TokenEndpoint
  [23:27:53 INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.TokenEndpoint for /connect/token
  [23:27:53 DBG] Start token request.
  [23:27:53 DBG] Start client validation
  [23:27:53 DBG] Start parsing Basic Authentication secret
  [23:27:53 DBG] Start parsing for secret in post body
  [23:27:53 DBG] client id without secret found
  [23:27:53 DBG] Parser found secret: PostBodySecretParser
  [23:27:53 DBG] Secret id found: Client_App
  [23:27:53 DBG] client configuration validation for client Client_App succeeded.
  [23:27:53 DBG] Public Client - skipping secret validation success
  [23:27:53 DBG] Client validation success
  [23:27:53 INF] {"ClientId": "Client_App", "AuthenticationMethod": "NoSecret", "Category": "Authentication", "Name": "Client Authentication Success", "EventType": "Success", "Id": 1010, "Message": null, "ActivityId": "80000182-0003-f700-b63f-84710c7967bb", "TimeStamp": "2021-03-31T12:27:53.0000000Z", "ProcessId": 10416, "LocalIpAddress": "127.0.0.1:44362", "RemoteIpAddress": "127.0.0.1", "$type": "ClientAuthenticationSuccessEvent"}
  [23:27:53 DBG] Start token request validation
  [23:27:53 DBG] Start validation of refresh token request
  [23:27:53 DBG] Validation of refresh token request success
  [23:27:53 INF] Token request validation success, {"ClientId": "Client_App", "ClientName": "Client_App", "GrantType": "refresh_token", "Scopes": null, "AuthorizationCode": "********", "RefreshToken": "****ED42", "UserName": null, "AuthenticationContextReferenceClasses": null, "Tenant": null, "IdP": null, "Raw": {"grant_type": "refresh_token", "scope": "offline_access Client", "refresh_token": "***REDACTED***", "client_id": "Client_App"}, "$type": "TokenRequestValidationLog"}
  [23:27:53 DBG] Updating refresh token
  [23:27:53 DBG] Token usage is one-time only. Setting current handle as consumed, and generating new handle
  [23:27:53 DBG] Created refresh token in store
  [23:27:53 DBG] Getting claims for identity token for subject: 39fb0cd8-5993-8e42-b1a5-e791f73d1e9f and client: Client_App
  [23:27:53 INF] {"ClientId": "Client_App", "ClientName": "Client_App", "RedirectUri": null, "Endpoint": "Token", "SubjectId": "39fb0cd8-5993-8e42-b1a5-e791f73d1e9f", "Scopes": "openid Client offline_access", "GrantType": "refresh_token", "Tokens": [{"TokenType": "id_token", "TokenValue": "****4Wmw", "$type": "Token"}, {"TokenType": "refresh_token", "TokenValue": "****62BC", "$type": "Token"}, {"TokenType": "access_token", "TokenValue": "****l3yQ", "$type": "Token"}], "Category": "Token", "Name": "Token Issued Success", "EventType": "Success", "Id": 2000, "Message": null, "ActivityId": "80000182-0003-f700-b63f-84710c7967bb", "TimeStamp": "2021-03-31T12:27:53.0000000Z", "ProcessId": 10416, "LocalIpAddress": "127.0.0.1:44362", "RemoteIpAddress": "127.0.0.1", "$type": "TokenIssuedSuccessEvent"}
  [23:27:53 DBG] Token request success.
  [23:27:53 INF] Request finished HTTP/2 POST [https://localhost:44362/connect/token](https://localhost:44362/connect/token) application/x-www-form-urlencoded 160 - 200 - application/json;+charset=UTF-8 123.8776ms
  
  [REMOVED MULTIPLE REPEATING TOEKN REFRESH SUCCESS BLOCKS]
  
  [23:53:08 INF] Request starting HTTP/2 OPTIONS [https://localhost:44362/connect/token](https://localhost:44362/connect/token) - -
  [23:53:08 INF] CORS policy execution successful.
  [23:53:08 INF] Request finished HTTP/2 OPTIONS [https://localhost:44362/connect/token](https://localhost:44362/connect/token) - - - 204 - - 0.3562ms
  [23:53:08 INF] Request starting HTTP/2 POST [https://localhost:44362/connect/token](https://localhost:44362/connect/token) application/x-www-form-urlencoded 160
  [23:53:08 INF] CORS policy execution successful.
  [23:53:08 INF] Successfully validated the token.
  [23:53:08 DBG] CORS request made for path: /connect/token from origin: [http://localhost:4200](http://localhost:4200)
  [23:53:08 DBG] CorsPolicyService allowed origin: [http://localhost:4200](http://localhost:4200)
  [23:53:08 INF] CORS policy execution successful.
  [23:53:08 DBG] Request path /connect/token matched to endpoint type Token
  [23:53:08 DBG] Endpoint enabled: Token, successfully created handler: IdentityServer4.Endpoints.TokenEndpoint
  [23:53:08 INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.TokenEndpoint for /connect/token
  [23:53:08 DBG] Start token request.
  [23:53:08 DBG] Start client validation
  [23:53:08 DBG] Start parsing Basic Authentication secret
  [23:53:08 DBG] Start parsing for secret in post body
  [23:53:08 DBG] client id without secret found
  [23:53:08 DBG] Parser found secret: PostBodySecretParser
  [23:53:08 DBG] Secret id found: Client_App
  [23:53:08 DBG] client configuration validation for client Client_App succeeded.
  [23:53:08 DBG] Public Client - skipping secret validation success
  [23:53:08 DBG] Client validation success
  [23:53:08 INF] {"ClientId": "Client_App", "AuthenticationMethod": "NoSecret", "Category": "Authentication", "Name": "Client Authentication Success", "EventType": "Success", "Id": 1010, "Message": null, "ActivityId": "800001f6-0004-ea00-b63f-84710c7967bb", "TimeStamp": "2021-03-31T12:53:08.0000000Z", "ProcessId": 10416, "LocalIpAddress": "127.0.0.1:44362", "RemoteIpAddress": "127.0.0.1", "$type": "ClientAuthenticationSuccessEvent"}
  [23:53:08 DBG] Start token request validation
  [23:53:08 DBG] Start validation of refresh token request
  [23:53:08 WRN] Refresh token has expired.
  [23:53:08 WRN] Refresh token validation failed. aborting, {"ClientId": "Client_App", "ClientName": "Client_App", "GrantType": "refresh_token", "Scopes": null, "AuthorizationCode": "********", "RefreshToken": "********", "UserName": null, "AuthenticationContextReferenceClasses": null, "Tenant": null, "IdP": null, "Raw": {"grant_type": "refresh_token", "scope": "offline_access Client", "refresh_token": "***REDACTED***", "client_id": "Client_App"}, "$type": "TokenRequestValidationLog"}
  [23:53:08 INF] {"ClientId": "Client_App", "ClientName": "Client_App", "RedirectUri": null, "Endpoint": "Token", "SubjectId": null, "Scopes": null, "GrantType": "refresh_token", "Error": "invalid_grant", "ErrorDescription": null, "Category": "Token", "Name": "Token Issued Failure", "EventType": "Failure", "Id": 2001, "Message": null, "ActivityId": "800001f6-0004-ea00-b63f-84710c7967bb", "TimeStamp": "2021-03-31T12:53:08.0000000Z", "ProcessId": 10416, "LocalIpAddress": "127.0.0.1:44362", "RemoteIpAddress": "127.0.0.1", "$type": "TokenIssuedFailureEvent"}
  [23:53:08 INF] Request finished HTTP/2 POST [https://localhost:44362/connect/token](https://localhost:44362/connect/token) application/x-www-form-urlencoded 160 - 400 - application/json;+charset=UTF-8 41.7969ms
  [23:56:04 INF] Request starting HTTP/2 OPTIONS [https://localhost:44362/.well-known/openid-configuration](https://localhost:44362/.well-known/openid-configuration) - -
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 INF] Request finished HTTP/2 OPTIONS [https://localhost:44362/.well-known/openid-configuration](https://localhost:44362/.well-known/openid-configuration) - - - 204 - - 0.9833ms
  [23:56:04 INF] Request starting HTTP/2 GET [https://localhost:44362/.well-known/openid-configuration](https://localhost:44362/.well-known/openid-configuration) - -
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 INF] Successfully validated the token.
  [23:56:04 DBG] CORS request made for path: /.well-known/openid-configuration from origin: [http://localhost:4200](http://localhost:4200)
  [23:56:04 DBG] CorsPolicyService allowed origin: [http://localhost:4200](http://localhost:4200)
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 DBG] Request path /.well-known/openid-configuration matched to endpoint type Discovery
  [23:56:04 DBG] Endpoint enabled: Discovery, successfully created handler: IdentityServer4.Endpoints.DiscoveryEndpoint
  [23:56:04 INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.DiscoveryEndpoint for /.well-known/openid-configuration
  [23:56:04 DBG] Start discovery request
  [23:56:04 INF] Request finished HTTP/2 GET [https://localhost:44362/.well-known/openid-configuration](https://localhost:44362/.well-known/openid-configuration) - - - 200 - application/json;+charset=UTF-8 29.5408ms
  [23:56:04 INF] Request starting HTTP/2 OPTIONS [https://localhost:44362/.well-known/openid-configuration/jwks](https://localhost:44362/.well-known/openid-configuration/jwks) - -
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 INF] Request finished HTTP/2 OPTIONS [https://localhost:44362/.well-known/openid-configuration/jwks](https://localhost:44362/.well-known/openid-configuration/jwks) - - - 204 - - 0.2289ms
  [23:56:04 INF] Request starting HTTP/2 GET [https://localhost:44362/.well-known/openid-configuration/jwks](https://localhost:44362/.well-known/openid-configuration/jwks) - -
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 INF] Successfully validated the token.
  [23:56:04 DBG] CORS request made for path: /.well-known/openid-configuration/jwks from origin: [http://localhost:4200](http://localhost:4200)
  [23:56:04 DBG] CorsPolicyService allowed origin: [http://localhost:4200](http://localhost:4200)
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 DBG] Request path /.well-known/openid-configuration/jwks matched to endpoint type Discovery
  [23:56:04 DBG] Endpoint enabled: Discovery, successfully created handler: IdentityServer4.Endpoints.DiscoveryKeyEndpoint
  [23:56:04 INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.DiscoveryKeyEndpoint for /.well-known/openid-configuration/jwks
  [23:56:04 DBG] Start key discovery request
  [23:56:04 INF] Request finished HTTP/2 GET [https://localhost:44362/.well-known/openid-configuration/jwks](https://localhost:44362/.well-known/openid-configuration/jwks) - - - 200 - application/json;+charset=UTF-8 10.8135ms
  [23:56:04 INF] Request starting HTTP/2 OPTIONS [https://localhost:44362/connect/token](https://localhost:44362/connect/token) - -
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 INF] Request finished HTTP/2 OPTIONS [https://localhost:44362/connect/token](https://localhost:44362/connect/token) - - - 204 - - 0.2310ms
  [23:56:04 INF] Request starting HTTP/2 POST [https://localhost:44362/connect/token](https://localhost:44362/connect/token) application/x-www-form-urlencoded 160
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 INF] Successfully validated the token.
  [23:56:04 DBG] CORS request made for path: /connect/token from origin: [http://localhost:4200](http://localhost:4200)
  [23:56:04 DBG] CorsPolicyService allowed origin: [http://localhost:4200](http://localhost:4200)
  [23:56:04 INF] CORS policy execution successful.
  [23:56:04 DBG] Request path /connect/token matched to endpoint type Token
  [23:56:04 DBG] Endpoint enabled: Token, successfully created handler: IdentityServer4.Endpoints.TokenEndpoint
  [23:56:04 INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.TokenEndpoint for /connect/token
  [23:56:04 DBG] Start token request.
  [23:56:04 DBG] Start client validation
  [23:56:04 DBG] Start parsing Basic Authentication secret
  [23:56:04 DBG] Start parsing for secret in post body
  [23:56:04 DBG] client id without secret found
  [23:56:04 DBG] Parser found secret: PostBodySecretParser
  [23:56:04 DBG] Secret id found: Client_App
  [23:56:04 DBG] client configuration validation for client Client_App succeeded.
  [23:56:04 DBG] Public Client - skipping secret validation success
  [23:56:04 DBG] Client validation success
  [23:56:04 INF] {"ClientId": "Client_App", "AuthenticationMethod": "NoSecret", "Category": "Authentication", "Name": "Client Authentication Success", "EventType": "Success", "Id": 1010, "Message": null, "ActivityId": "8000053f-0005-e500-b63f-84710c7967bb", "TimeStamp": "2021-03-31T12:56:04.0000000Z", "ProcessId": 10416, "LocalIpAddress": "127.0.0.1:44362", "RemoteIpAddress": "127.0.0.1", "$type": "ClientAuthenticationSuccessEvent"}
  [23:56:04 DBG] Start token request validation
  [23:56:04 DBG] Start validation of refresh token request
  [23:56:04 WRN] Refresh token has expired.
  [23:56:04 WRN] Refresh token validation failed. aborting, {"ClientId": "Client_App", "ClientName": "Client_App", "GrantType": "refresh_token", "Scopes": null, "AuthorizationCode": "********", "RefreshToken": "********", "UserName": null, "AuthenticationContextReferenceClasses": null, "Tenant": null, "IdP": null, "Raw": {"grant_type": "refresh_token", "scope": "offline_access Client", "refresh_token": "***REDACTED***", "client_id": "Client_App"}, "$type": "TokenRequestValidationLog"}
  [23:56:04 INF] {"ClientId": "Client_App", "ClientName": "Client_App", "RedirectUri": null, "Endpoint": "Token", "SubjectId": null, "Scopes": null, "GrantType": "refresh_token", "Error": "invalid_grant", "ErrorDescription": null, "Category": "Token", "Name": "Token Issued Failure", "EventType": "Failure", "Id": 2001, "Message": null, "ActivityId": "8000053f-0005-e500-b63f-84710c7967bb", "TimeStamp": "2021-03-31T12:56:04.0000000Z", "ProcessId": 10416, "LocalIpAddress": "127.0.0.1:44362", "RemoteIpAddress": "127.0.0.1", "$type": "TokenIssuedFailureEvent"}
  [23:56:04 INF] Request finished HTTP/2 POST [https://localhost:44362/connect/token](https://localhost:44362/connect/token) application/x-www-form-urlencoded 160 - 400 - application/json;+charset=UTF-8 31.2436ms
  

  Save Cancel
• 

  0

  riley.trevillion created 3 years ago

  IdentityServerClients DBTable

  ---

  <br> <br>

  Id,ClientId,ClientName,Description,ClientUri,LogoUri,Enabled,ProtocolType,RequireClientSecret,RequireConsent,AllowRememberConsent,AlwaysIncludeUserClaimsInIdToken,RequirePkce,AllowPlainTextPkce,RequireRequestObject,AllowAccessTokensViaBrowser,FrontChannelLogoutUri,FrontChannelLogoutSessionRequired,BackChannelLogoutUri,BackChannelLogoutSessionRequired,AllowOfflineAccess,IdentityTokenLifetime,AllowedIdentityTokenSigningAlgorithms,AccessTokenLifetime,AuthorizationCodeLifetime,ConsentLifetime,AbsoluteRefreshTokenLifetime,SlidingRefreshTokenLifetime,RefreshTokenUsage,UpdateAccessTokenClaimsOnRefresh,RefreshTokenExpiration,AccessTokenType,EnableLocalLogin,IncludeJwtId,AlwaysSendClientClaims,ClientClaimsPrefix,PairWiseSubjectSalt,UserSsoLifetime,UserCodeType,DeviceCodeLifetime,ExtraProperties,ConcurrencyStamp,CreationTime,CreatorId,LastModificationTime,LastModifierId,IsDeleted,DeleterId,DeletionTime
  39fb0cd8-5ebd-d891-7227-41d8bdb599c4,Client_Swagger,Client_Swagger,Client_Swagger,,,t,oidc,f,f,t,t,f,f,f,f,,t,,t,t,300,,31536000,300,,31536000,1296000,1,f,1,0,t,f,f,client_,,,,300,{},d17f0620c203454b9a9aec1fffacd6e2,38:01.2,,38:01.2,,f,,
  39fb0cd8-5e77-c65d-6d9b-b4a467324d69,Client_App,Client_App,Client_App,,,t,oidc,f,f,t,t,f,f,f,f,,t,,t,t,300,,400,300,,1800,900,1,f,1,0,t,f,f,client_,,,,300,{},2577c8202df3412db530849fa91dc765,38:01.1,,15:01.1,39fb0cd8-5993-8e42-b1a5-e791f73d1e9f,f,,
  

  Save Cancel
• 

  0

  Mehmet created 3 years ago

  Hi

  I've created an issue: https://github.com/abpframework/abp/issues/8580

  It will be fixed in v4.3 stable version. Thanks for the reporting.

  Save Cancel

  1
• 

  0

  ServiceBot created 3 years ago

  Support Team Automatic process manager

  This question has been automatically marked as stale because it has not had recent activity.

  Save Cancel