Azure / azure-functions-microsoftgraph-extension

Microsoft Graph extension for Azure Functions
MIT License
46 stars 23 forks source link

Credentials time out even though cookie still valid #52

Open ConnorMcMahon opened 6 years ago

ConnorMcMahon commented 6 years ago

When using the token mode UserFromRequest, a user encountered the below issue.

2018-04-06T13:24:47.145 [Error] System.Private.CoreLib: Exception while executing function: Functions.getCalendar. Microsoft.Azure.WebJobs.Host: Exception binding parameter 'graphToken'. Microsoft.IdentityModel.Clients.ActiveDirectory: AADSTS70002: Error validating credentials. AADSTS50013: Assertion is not within its valid time range. Trace ID: e9c4c023-b531-45a4-a63c-be4f2e621000 Correlation ID: f5886be0-6846-484f-9d4b-b10711a8047c Timestamp: 2018-04-06 13:24:46Z. Microsoft.IdentityModel.Clients.ActiveDirectory: Response status code does not indicate success: 400 (BadRequest). {"error":"invalid_grant","error_description":"AADSTS70002: Error validating credentials. AADSTS50013: Assertion is not within its valid time range.\r\nTrace ID: e9c4c023-b531-45a4-a63c-be4f2e621000\r\nCorrelation ID: f5886be0-6846-484f-9d4b-b10711a8047c\r\nTimestamp: 2018-04-06 13:24:46Z","error_codes":[70002,50013],"timestamp":"2018-04-06 13:24:46Z","trace_id":"e9c4c023-b531-45a4-a63c-be4f2e621000","correlation_id":"f5886be0-6846-484f-9d4b-b10711a8047c"}. 2018-04-06T13:24:47.489 [Error] Executed 'Functions.getCalendar' (Failed, Id=ae18d8ff-2e42-4f0e-a761-bbc9c33bbf9f)

The user could sign into other sites, so their cookie was still valid.

svengillis commented 6 years ago

Any updates on this? Thanks

ConnorMcMahon commented 6 years ago

I haven't had a chance to investigate this yet. If anyone has experienced this issue, if they could give me a time estimate of how long it took after initially logging into their application that this issue was encountered, that would be a huge help in tracking down this issue.

svengillis commented 6 years ago

It expires after 1 hour, so it has something to do with the Access token.

t-yaegashi commented 6 years ago

I've just had the same problem. I could recover from errors by performing the following steps:

  1. Access /.auth/refresh
  2. Delete AppServiceAuthSession cookie on the function app host
  3. Sign in again on the function app host

I'm not sure whether it's the correct way to remove the cause of errors. I had never touched /.auth/logout so supposedly I kept being signed in on Azure AD IdP.

Microsoft.Azure.WebJobs.Host.FunctionInvocationException: Exception while executing function: BillingPeriodsPublish ---> System.InvalidOperationException: Exception binding parameter 'graphToken' ---> Microsoft.IdentityModel.Clients.ActiveDirectory.AdalServiceException: AADSTS70002: Error validating credentials. AADSTS50013: Assertion is not within its valid time range.
Trace ID: 7b6edc83-9a9e-485c-81a1-b16bfe136100
Correlation ID: ddc0dd0c-290c-4e71-9292-7950cb6975cc
Timestamp: 2018-09-25 17:19:35Z ---> System.Net.Http.HttpRequestException:  Response status code does not indicate success: 400 (BadRequest). ---> System.Exception: {"error":"invalid_grant","error_description":"AADSTS70002: Error validating credentials. AADSTS50013: Assertion is not within its valid time range.\r\nTrace ID: 7b6edc83-9a9e-485c-81a1-b16bfe136100\r\nCorrelation ID: ddc0dd0c-290c-4e71-9292-7950cb6975cc\r\nTimestamp: 2018-09-25 17:19:35Z","error_codes":[70002,50013],"timestamp":"2018-09-25 17:19:35Z","trace_id":"7b6edc83-9a9e-485c-81a1-b16bfe136100","correlation_id":"ddc0dd0c-290c-4e71-9292-7950cb6975cc"}
   --- End of inner exception stack trace ---
   at Microsoft.IdentityModel.Clients.ActiveDirectory.HttpClientWrapper.GetResponseAsync()
   --- End of inner exception stack trace ---
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AdalHttpClient.GetResponseAsync[T](Boolean respondToDeviceAuthChallenge)
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AdalHttpClient.GetResponseAsync[T]()
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AcquireTokenHandlerBase.SendHttpMessageAsync(IRequestParameters requestParameters)
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AcquireTokenHandlerBase.SendTokenRequestAsync()
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AcquireTokenOnBehalfHandler.SendTokenRequestAsync()
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AcquireTokenHandlerBase.RunAsync()
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AuthenticationContext.AcquireTokenOnBehalfCommonAsync(String resource, ClientKey clientKey, UserAssertion userAssertion)
   at Microsoft.IdentityModel.Clients.ActiveDirectory.AuthenticationContext.AcquireTokenAsync(String resource, ClientCredential clientCredential, UserAssertion userAssertion)
   at Microsoft.Azure.WebJobs.Extensions.AuthTokens.AadClient.GetTokenOnBehalfOfUserAsync(String userToken, String resource)
   at Microsoft.Azure.WebJobs.Extensions.AuthTokens.TokenConverter.GetAuthTokenFromUserToken(String userToken, String resource)
   at Microsoft.Azure.WebJobs.Extensions.AuthTokens.TokenConverter.ConvertAsync(TokenBaseAttribute attribute, CancellationToken cancellationToken)
   at Microsoft.Azure.WebJobs.Extensions.AuthTokens.TokenConverter.ConvertAsync(TokenAttribute attribute, CancellationToken cancellationToken)
   at Microsoft.Azure.WebJobs.Host.Bindings.PatternMatcher.AsyncInvoker`2.<>c__DisplayClass0_0.<<Execute>b__0>d.MoveNext() in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Bindings\PatternMatcher.cs:line 383
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.WebJobs.Host.Bindings.BindToInputBindingProvider`2.ExactBinding.BuildAsync(TAttribute attrResolved, ValueBindingContext context) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Bindings\BindingProviders\BindToInputBindingProvider.cs:line 212
   at Microsoft.Azure.WebJobs.Host.Bindings.BindingBase`1.BindAsync(BindingContext context) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Bindings\BindingBase.cs:line 50
   at Microsoft.Azure.WebJobs.Host.Triggers.TriggeredFunctionBinding`1.BindCoreAsync(ValueBindingContext context, Object value, IDictionary`2 parameters) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Triggers\TriggeredFunctionBinding.cs:line 98
   --- End of inner exception stack trace ---
   at Microsoft.Azure.WebJobs.Host.Executors.DelayedException.Throw() in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\DelayedException.cs:line 27
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithWatchersAsync(IFunctionInstance instance, ParameterHelper parameterHelper, ILogger logger, CancellationTokenSource functionCancellationTokenSource) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 478
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstance instance, ParameterHelper parameterHelper, IFunctionOutputDefinition outputDefinition, ILogger logger, CancellationTokenSource functionCancellationTokenSource) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 444
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstance instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 249
   --- End of inner exception stack trace ---
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstance instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 293
   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance, CancellationToken cancellationToken) in C:\projects\azure-webjobs-sdk-rqm4t\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 89
t-yaegashi commented 6 years ago

I got the same exception after 2 hours since recovering from errors, and recovered again by erasing cookies. Here's the summary of the report from Application Insights for the function app host:

Time What happened
2018-09-25T17:35:54Z Recovered from errors by performing steps in the previous comment, there's access token to expire at 2018-09-25T18:35:54.0000000Z according to /.auth/me
2018-09-25T18:44:02Z The access token had already expired, but the service still worked, it was able to access https://graph.microsoft.com resources
2018-09-25T19:04:05Z Stopping JobHost (due to being idle?)
2018-09-25T19:32:11Z Starting JobHost (due to a new request?)
2018-09-25T19:32:12Z Incoming request appeared
2018-09-25T19:32:13Z It made outgoing POST to https://sts.windows.net/.../oauth2/token and got 400 Bad request
2018-09-25T19:32:14Z It raised the same exception shown in the previous comment
2018-09-25T20:10:04Z Stopping JobHost
2018-09-25T20:14:00Z /.auth/me still showed "expires_on":"2018-09-25T18:35:54.0000000Z"
2018-09-25T20:15:00Z Made access to /.auth/refresh by a web browser
2018-09-25T20:15:40Z /.auth/me changed to "expires_on":"2018-09-25T21:15:40.0000000Z"
2018-09-25T20:17:15Z Starting JobHost
2018-09-25T20:17:16Z Incoming request appeared
2018-09-25T20:17:17Z It made outgoing POST to https://sts.windows.net/.../oauth2/token and still got 400 Bad request
2018-09-25T20:17:17Z It raised the same exception again
2018-09-25T20:25:10Z Deleted AppServiceAuthSession cookie in the web browser
2018-09-25T20:26:30Z Made access to the function app host by the web browser, got redirected to Azure AD IdP and prompted to sign in. Started a fresh signed in session
2018-09-25T20:26:34Z Incoming request appeared
2018-09-25T20:26:35Z It made outgoing POST to https://sts.windows.net/.../oauth2/token and it was a successfull call
2018-09-25T20:27:08Z It finished to handle the request successfully after accessing to https://graph.microsoft.com and other resources
DouglasHeriot commented 5 years ago

I have this same issue - have to go to http://.../.auth/login to refresh the token, even though it says I'm already logged in.