Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

known-issue: ExpiredAuthenticationToken when running a long-running operation #20867

Closed
1 task done
op7ic opened this issue Mar 9, 2023 · 51 comments
Closed
1 task done

Comments

@op7ic
Copy link

op7ic commented Mar 9, 2023

Is there an existing issue for this?

  • I have searched the existing issues

Community Note

  • Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
  • Please do not leave "+1" or "me too" comments, they generate extra noise for issue followers and do not help prioritize the request
  • If you are interested in working on this issue or have submitted a pull request, please leave a comment

Terraform Version

1.3.9

AzureRM Provider Version

3.46.0

Affected Resource(s)/Data Source(s)

azurerm_active_directory_domain_service

Terraform Configuration Files

[...]
resource "azurerm_active_directory_domain_service" "test" {
  name                  = "ad"
  location              = azurerm_resource_group.aadds.location
  resource_group_name   = azurerm_resource_group.aadds.name
  filtered_sync_enabled = false
  domain_name           = "test.test.com"
  sku                   = "Standard"

  initial_replica_set {
    subnet_id = azurerm_subnet.aadds.id
  }

  notifications {
    notify_dc_admins      = true
    notify_global_admins  = true
  }

  security {
    sync_kerberos_passwords = true
    sync_ntlm_passwords     = true
    sync_on_prem_passwords  = true
  }
  
  timeouts {
    create = "12h"
    update = "12h"
    read = "120m"
    delete = "12h"
  }

  tags = {
    environment = "prod"
  }
}
[...]


### Debug Output/Panic Output

```shell
Error: creating/updating Domain Service (Name: "ad", Resource Group: "test"): polling after CreateOrUpdate: Future#WaitForCompletion: the number of retries has been exceeded: StatusCode=401 -- Original Error: Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '3/9/2023 11:01:31 AM' is earlier than current UTC time '3/9/2023 11:05:09 AM'.


### Expected Behaviour

Build process should finish successfully despite long build time.

### Actual Behaviour

The build process for the azurerm_active_directory_domain_service resource takes over 1.5h which means that, before build is completed, the authentication token expires. As the polling for completion is done every 10 seconds, eventually the authentication token will expire mid-way through build process and whole resource creation will fail resulting in the above error. 

### Steps to Reproduce

terraform apply


### Important Factoids

No

### References

None
@op7ic op7ic added the bug label Mar 9, 2023
@github-actions github-actions bot removed the bug label Mar 9, 2023
@magodo
Copy link
Collaborator

magodo commented Mar 13, 2023

@op7ic From the error code, it seems the token is expired and somehow not refreshed. Would you please provide the debug log so that we can further investigate?

@op7ic
Copy link
Author

op7ic commented Mar 13, 2023

hi @magodo that's correct - it exactly what happens mid-way through build. I'll get the log and upload it here.

@tombuildsstuff
Copy link
Contributor

@op7ic I believe the root cause (the auth token not renewing correctly in all cases) has been fixed in v3.47.0, would you mind updating to the latest version and seeing if that works for you?

@op7ic
Copy link
Author

op7ic commented Mar 13, 2023

@tombuildsstuff sure let me try. In the meantime here is the last error from debug log:

{"error":{"code":"ExpiredAuthenticationToken","message":"The access token expiry UTC time '3/13/2023 6:48:43 PM' is earlier than current UTC time '3/13/2023 6:48:59 PM'."}}: timestamp=2023-03-13T21:49:01.030+0300
2023-03-13T21:49:01.030+0300 [DEBUG] provider.terraform-provider-azurerm_v3.46.0_x5: Unlocking "azurerm_active_directory_domain_service.ad": timestamp=2023-03-13T21:49:01.030+0300
2023-03-13T21:49:01.030+0300 [DEBUG] provider.terraform-provider-azurerm_v3.46.0_x5: Unlocked "azurerm_active_directory_domain_service.ad": timestamp=2023-03-13T21:49:01.030+0300
2023-03-13T21:49:01.032+0300 [ERROR] provider.terraform-provider-azurerm_v3.46.0_x5: Response contains error diagnostic: diagnostic_severity=ERROR tf_proto_version=5.3 tf_req_id=xxxxxxxxxxx tf_resource_type=azurerm_active_directory_domain_service @caller=github.com/hashicorp/[email protected]/tfprotov5/internal/diag/diagnostics.go:55 @module=sdk.proto diagnostic_detail= diagnostic_summary="waiting for both domain controllers to become available in initial replica set for Domain Service: (Initial Replica Set Id Name "xxxxxxxx" / Name "xxxxx" / Resource Group "xxxxxxxx"): domainservices.DomainServicesClient#Get: Failure responding to request: StatusCode=401 -- Original Error: autorest/azure: Service returned an error. Status=401 Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '3/13/2023 6:48:43 PM' is earlier than current UTC time '3/13/2023 6:48:59 PM'."" tf_provider_addr=provider tf_rpc=ApplyResourceChange timestamp=2023-03-13T21:49:01.032+0300
2023-03-13T21:49:01.141+0300 [ERROR] vertex "azurerm_active_directory_domain_service.aadds" error: waiting for both domain controllers to become available in initial replica set for Domain Service: (Initial Replica Set Id Name "xxxxx" / Name "xxxxx" / Resource Group "xxxxx"): domainservices.DomainServicesClient#Get: Failure responding to request: StatusCode=401 -- Original Error: autorest/azure: Service returned an error. Status=401 Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '3/13/2023 6:48:43 PM' is earlier than current UTC time '3/13/2023 6:48:59 PM'."
2023-03-13T22:19:02.969+0300 [DEBUG] provider.stdio: received EOF, stopping recv loop: err="rpc error: code = Unavailable desc = error reading from server: EOF"
2023-03-13T22:19:02.969+0300 [DEBUG] provider.stdio: received EOF, stopping recv loop: err="rpc error: code = Unavailable desc = error reading from server: EOF"
2023-03-13T22:19:02.969+0300 [DEBUG] provider.stdio: received EOF, stopping recv loop: err="rpc error: code = Unavailable desc = error reading from server: EOF"
2023-03-13T22:19:02.970+0300 [DEBUG] provider: plugin process exited: path=.terraform/providers/registry.terraform.io/hashicorp/random/3.4.3/linux_amd64/terraform-provider-random_v3.4.3_x5 pid=27702
2023-03-13T22:19:02.970+0300 [DEBUG] provider: plugin exited
2023-03-13T22:19:02.970+0300 [DEBUG] provider: plugin process exited: path=.terraform/providers/registry.terraform.io/hashicorp/null/3.2.1/linux_amd64/terraform-provider-null_v3.2.1_x5 pid=27694
2023-03-13T22:19:02.970+0300 [DEBUG] provider: plugin exited
2023-03-13T22:19:02.974+0300 [DEBUG] provider: plugin process exited: path=.terraform/providers/registry.terraform.io/hashicorp/azurerm/3.46.0/linux_amd64/terraform-provider-azurerm_v3.46.0_x5 pid=27711
2023-03-13T22:19:02.974+0300 [DEBUG] provider: plugin exited

@magodo
Copy link
Collaborator

magodo commented Mar 14, 2023

@tombuildsstuff Probabaly it is v3.48.0, per #20894?

@op7ic
Copy link
Author

op7ic commented Mar 14, 2023

@magodo I believe 3.48.0 is not yet published but 3.47.0 is as per https://registry.terraform.io/providers/hashicorp/azurerm/latest. I'll try 3.47 first and report back to see if there is an improvement.

@tombuildsstuff
Copy link
Contributor

@op7ic 🤦 apologies for the confusion, I thought that the fix (#20894) went into 3.47.0 last week, but @magodo is right, that'll ship in 3.48.0 later this week

@op7ic
Copy link
Author

op7ic commented Mar 14, 2023

@tombuildsstuff / @magodo I can confirm that 3.47.0 is still the same. I'll test 3.48 once it arrives but looking at commitment code for the release it seems that it should work ;)

@tombuildsstuff
Copy link
Contributor

Sounds good - since #20894 has been merged and this'll go out in this weeks release - I'm going to close this issue for the moment and assign this to this weeks milestone, once the release is out then a comment will be posted - but if this still an issue in v3.48 then please let us know and we can take another look 👍

@github-actions
Copy link

This functionality has been released in v3.48.0 of the Terraform Provider. Please see the Terraform documentation on provider versioning or reach out if you need any assistance upgrading.

For further feature requests or bug reports with this functionality, please create a new GitHub issue following the template. Thank you!

@garbology
Copy link

@tombuildsstuff
This is still an issue with v3.48.0, experienced when building the SQL Managed Instance using azurerm_mssql_managed_instance.
At the 60 min mark:

waiting for creation of Managed Instance: (Name "[SQLMI-name]" / Resource Group "[RG-name]"): Future#WaitForCompletion: the number of retries has  
been exceeded: StatusCode=401 -- Original Error: Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '3/17/2023 2:24:05 AM' is earlier  
than current UTC time '3/17/2023 2:27:38 AM'.

@magodo magodo reopened this Mar 17, 2023
@tombuildsstuff
Copy link
Contributor

@manicminer mind taking a look into this one?

@manicminer
Copy link
Contributor

manicminer commented Mar 17, 2023

@garbology Would you be able to provide a debug log showing the error and requests that led to it? Also, can you confirm your system clock is accurate where Terraform is running? Thanks.

@op7ic
Copy link
Author

op7ic commented Mar 19, 2023

@manicminer / @tombuildsstuff Just for completness, I can confirm that the same symptom appears on v3.48 for AD creation as noted above. Around an hour mark the session expires. Here is debug log from this:

{"error":{"code":"ExpiredAuthenticationToken","message":"The access token expiry UTC time '3/19/2023 11:33:34 AM' is earlier than current UTC time '3/19/2023 11:33:39 AM'."}}: timestamp=2023-03-19T14:33:39.637+0300
2023-03-19T14:33:40.270+0300 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5: AzureRM Request: 
GET /subscriptions/xxxxxxx/providers/Microsoft.Compute/locations/uksouth/operations/xxxxxxx&api-version=2022-08-01 HTTP/1.1
Host: management.azure.com
User-Agent: Go/go1.19.3 (amd64-linux) go-autorest/v14.2.1 tombuildsstuff/kermit/v0.20230307.1105329 compute/2022-08-01 HashiCorp Terraform/1.3.9 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820
X-Ms-Correlation-Request-Id: xxxxxxx
Accept-Encoding: gzip: timestamp=2023-03-19T14:33:40.270+0300
2023-03-19T14:33:40.505+0300 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5: AzureRM Response for https://management.azure.com/subscriptions/xxxxxxx/providers/Microsoft.Compute/locations/uksouth/operations/xxxxxxx?p=xxxxxxx&api-version=2022-08-01: 
HTTP/2.0 401 Unauthorized
Content-Length: 174
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
Date: Sun, 19 Mar 2023 11:33:39 GMT
Expires: -1
Pragma: no-cache
Strict-Transport-Security: max-age=31536000; includeSubDomains
Www-Authenticate: Bearer authorization_uri="https://login.windows.net/xxxxxxx", error="invalid_token", error_description="The access token has expired."
X-Content-Type-Options: nosniff
X-Ms-Correlation-Request-Id: xxxxxxx
X-Ms-Failure-Cause: gateway
X-Ms-Request-Id: xxxxxxx
X-Ms-Routing-Request-Id: EASTUS:20230319T113340Z:xxxxxxx

It appears that, so long creation of the resource, is less than an hour there are no problems. If resource creation takes over an hour then ExpiredAuthenticationToken error will appear.

@hcevensen
Copy link

Can confirm still happening for me when creating sqlmi around the hour mark also with 3.48 , using 3.43 it has no issues

@garbology
Copy link

@manicminer
System clock is accurate.

2023-03-19T19:54:56.120+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Response for https://management.azure.com/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview: 
HTTP/2.0 200 OK
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
Date: Sun, 19 Mar 2023 08:54:56 GMT
Expires: -1
Pragma: no-cache
Server: Microsoft-HTTPAPI/2.0
Strict-Transport-Security: max-age=31536000; includeSubDomains
Vary: Accept-Encoding
X-Content-Type-Options: nosniff
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
X-Ms-Ratelimit-Remaining-Subscription-Reads: 11884
X-Ms-Request-Id: <Request-Id 1>
X-Ms-Routing-Request-Id: AUSTRALIASOUTHEAST:20230319T085456Z:x

{"identity":{"principalId":"<service principal>","type":"SystemAssigned","tenantId":"<tenant>"},"sku":{"name":"GP_Gen5","tier":"GeneralPurpose","family":"Gen5","capacity":4},"properties":{"provisioningState":"Creating","administratorLogin":"<Adminuser>","subnetId":"/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Network/virtualNetworks/vnet-test-2/subnets/sql_mi_subnet_2","state":"Creating","licenseType":"BasePrice","vCores":4,"storageSizeInGB":32,"collation":"SQL_Latin1_General_CP1_CI_AS","publicDataEndpointEnabled":false,"proxyOverride":"Default","timezoneId":"UTC","maintenanceConfigurationId":"/subscriptions/<subscription>/providers/Microsoft.Maintenance/publicMaintenanceConfigurations/SQL_Default","privateEndpointConnections":[],"minimalTlsVersion":"1.2","storageAccountType":"LRS","zoneRedundant":false},"location":"eastus","tags":{},"id":"/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>","name":"<SQL MI Name>","type":"Microsoft.Sql/managedInstances"}: timestamp=2023-03-19T19:54:56.120+1100

2023-03-19T19:55:26.128+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Request: 
GET /subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview HTTP/1.1
Host: management.azure.com
User-Agent: Go/go1.19.3 (amd64-windows) go-autorest/v14.2.1 Azure-SDK-For-Go/v66.0.0 sql/v5.0 HashiCorp Terraform/1.4.1 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
Accept-Encoding: gzip: timestamp=2023-03-19T19:55:26.128+1100

2023-03-19T19:55:27.423+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Response for https://management.azure.com/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview: 
HTTP/2.0 200 OK
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
Date: Sun, 19 Mar 2023 08:55:27 GMT
Expires: -1
Pragma: no-cache
Server: Microsoft-HTTPAPI/2.0
Strict-Transport-Security: max-age=31536000; includeSubDomains
Vary: Accept-Encoding
X-Content-Type-Options: nosniff
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
X-Ms-Ratelimit-Remaining-Subscription-Reads: 11883
X-Ms-Request-Id: <Request-Id 2>
X-Ms-Routing-Request-Id: AUSTRALIASOUTHEAST:20230319T085527Z:x

{"identity":{"principalId":"<service principal>","type":"SystemAssigned","tenantId":"<tenant>"},"sku":{"name":"GP_Gen5","tier":"GeneralPurpose","family":"Gen5","capacity":4},"properties":{"provisioningState":"Creating","administratorLogin":"<Adminuser>","subnetId":"/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Network/virtualNetworks/vnet-test-2/subnets/sql_mi_subnet_2","state":"Creating","licenseType":"BasePrice","vCores":4,"storageSizeInGB":32,"collation":"SQL_Latin1_General_CP1_CI_AS","publicDataEndpointEnabled":false,"proxyOverride":"Default","timezoneId":"UTC","maintenanceConfigurationId":"/subscriptions/<subscription>/providers/Microsoft.Maintenance/publicMaintenanceConfigurations/SQL_Default","privateEndpointConnections":[],"minimalTlsVersion":"1.2","storageAccountType":"LRS","zoneRedundant":false},"location":"eastus","tags":{},"id":"/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>","name":"<SQL MI Name>","type":"Microsoft.Sql/managedInstances"}: timestamp=2023-03-19T19:55:27.423+1100

2023-03-19T19:55:57.427+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Request: 
GET /subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview HTTP/1.1
Host: management.azure.com
User-Agent: Go/go1.19.3 (amd64-windows) go-autorest/v14.2.1 Azure-SDK-For-Go/v66.0.0 sql/v5.0 HashiCorp Terraform/1.4.1 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
Accept-Encoding: gzip: timestamp=2023-03-19T19:55:57.427+1100

2023-03-19T19:55:57.444+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Response for https://management.azure.com/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview: 
HTTP/2.0 401 Unauthorized
Content-Length: 172
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
Date: Sun, 19 Mar 2023 08:55:57 GMT
Expires: -1
Pragma: no-cache
Strict-Transport-Security: max-age=31536000; includeSubDomains
Www-Authenticate: Bearer authorization_uri="https://login.windows.net/<tenant>", error="invalid_token", error_description="The access token has expired."
X-Content-Type-Options: nosniff
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
X-Ms-Failure-Cause: gateway
X-Ms-Request-Id: <Request-Id 3>
X-Ms-Routing-Request-Id: AUSTRALIASOUTHEAST:20230319T085557Z:<Request-Id 3>

{"error":{"code":"ExpiredAuthenticationToken","message":"The access token expiry UTC time '3/19/2023 8:55:46 AM' is earlier than current UTC time '3/19/2023 8:55:57 AM'."}}: timestamp=2023-03-19T19:55:57.444+1100

2023-03-19T19:56:27.455+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Request: 
GET /subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview HTTP/1.1
Host: management.azure.com
User-Agent: Go/go1.19.3 (amd64-windows) go-autorest/v14.2.1 Azure-SDK-For-Go/v66.0.0 sql/v5.0 HashiCorp Terraform/1.4.1 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
Accept-Encoding: gzip: timestamp=2023-03-19T19:56:27.455+1100

2023-03-19T19:56:27.474+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Response for https://management.azure.com/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview: 
HTTP/2.0 401 Unauthorized
Content-Length: 172
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
Date: Sun, 19 Mar 2023 08:56:27 GMT
Expires: -1
Pragma: no-cache
Strict-Transport-Security: max-age=31536000; includeSubDomains
Www-Authenticate: Bearer authorization_uri="https://login.windows.net/<tenant>", error="invalid_token", error_description="The access token has expired."
X-Content-Type-Options: nosniff
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
X-Ms-Failure-Cause: gateway
X-Ms-Request-Id: <Request-Id 4>
X-Ms-Routing-Request-Id: AUSTRALIASOUTHEAST:20230319T085627Z:<Request-Id 4>

{"error":{"code":"ExpiredAuthenticationToken","message":"The access token expiry UTC time '3/19/2023 8:55:46 AM' is earlier than current UTC time '3/19/2023 8:56:27 AM'."}}: timestamp=2023-03-19T19:56:27.474+1100

2023-03-19T19:57:27.486+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Request: 
GET /subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview HTTP/1.1
Host: management.azure.com
User-Agent: Go/go1.19.3 (amd64-windows) go-autorest/v14.2.1 Azure-SDK-For-Go/v66.0.0 sql/v5.0 HashiCorp Terraform/1.4.1 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
Accept-Encoding: gzip: timestamp=2023-03-19T19:57:27.486+1100

2023-03-19T19:57:27.502+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Response for https://management.azure.com/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview: 
HTTP/2.0 401 Unauthorized
Content-Length: 172
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
Date: Sun, 19 Mar 2023 08:57:27 GMT
Expires: -1
Pragma: no-cache
Strict-Transport-Security: max-age=31536000; includeSubDomains
Www-Authenticate: Bearer authorization_uri="https://login.windows.net/<tenant>", error="invalid_token", error_description="The access token has expired."
X-Content-Type-Options: nosniff
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
X-Ms-Failure-Cause: gateway
X-Ms-Request-Id: <Request-Id 5>
X-Ms-Routing-Request-Id: AUSTRALIASOUTHEAST:20230319T085727Z:<Request-Id 5>

{"error":{"code":"ExpiredAuthenticationToken","message":"The access token expiry UTC time '3/19/2023 8:55:46 AM' is earlier than current UTC time '3/19/2023 8:57:27 AM'."}}: timestamp=2023-03-19T19:57:27.502+1100

2023-03-19T19:59:27.513+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Request: 
GET /subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview HTTP/1.1
Host: management.azure.com
User-Agent: Go/go1.19.3 (amd64-windows) go-autorest/v14.2.1 Azure-SDK-For-Go/v66.0.0 sql/v5.0 HashiCorp Terraform/1.4.1 (+https://www.terraform.io) Terraform Plugin SDK/2.10.1 terraform-provider-azurerm/dev pid-222c6c49-1b0a-5959-a213-6608f9eb8820
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
Accept-Encoding: gzip: timestamp=2023-03-19T19:59:27.513+1100
2023-03-19T19:59:27.528+1100 [DEBUG] provider.terraform-provider-azurerm_v3.48.0_x5.exe: AzureRM Response for https://management.azure.com/subscriptions/<subscription>/resourceGroups/test/providers/Microsoft.Sql/managedInstances/<SQL MI Name>?api-version=2020-11-01-preview: 
HTTP/2.0 401 Unauthorized
Content-Length: 172
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
Date: Sun, 19 Mar 2023 08:59:27 GMT
Expires: -1
Pragma: no-cache
Strict-Transport-Security: max-age=31536000; includeSubDomains
Www-Authenticate: Bearer authorization_uri="https://login.windows.net/<tenant>", error="invalid_token", error_description="The access token has expired."
X-Content-Type-Options: nosniff
X-Ms-Correlation-Request-Id: <Correlation-Request-Id>
X-Ms-Failure-Cause: gateway
X-Ms-Request-Id: <Request-Id 6>
X-Ms-Routing-Request-Id: AUSTRALIASOUTHEAST:20230319T085927Z:<Request-Id 6>

{"error":{"code":"ExpiredAuthenticationToken","message":"The access token expiry UTC time '3/19/2023 8:55:46 AM' is earlier than current UTC time '3/19/2023 8:59:27 AM'."}}: timestamp=2023-03-19T19:59:27.528+1100

2023-03-19T19:59:27.528+1100 [ERROR] provider.terraform-provider-azurerm_v3.48.0_x5.exe: Response contains error diagnostic: diagnostic_detail="waiting for creation of Managed Instance: (Name "<SQL MI Name>" / Resource Group "test"): Future#WaitForCompletion: the number of retries has been exceeded: StatusCode=401 -- Original Error: Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '3/19/2023 8:55:46 AM' is earlier than current UTC time '3/19/2023 8:59:27 AM'."" diagnostic_severity=ERROR diagnostic_summary="waiting for creation of Managed Instance: (Name "<SQL MI Name>" / Resource Group "test"): Future#WaitForCompletion: the number of retries has been exceeded: StatusCode=401 -- Original Error: Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '3/19/2023 8:55:46 AM' is earlier than current UTC time '3/19/2023 8:59:27 AM'."" tf_req_id=6a4ecbc0-83cf-0097-09fe-4afe278cd697 tf_rpc=ApplyResourceChange @caller=github.com/hashicorp/[email protected]/tfprotov5/internal/diag/diagnostics.go:55 @module=sdk.proto tf_provider_addr=provider tf_resource_type=azurerm_mssql_managed_instance tf_proto_version=5.3 timestamp=2023-03-19T19:59:27.528+1100
2023-03-19T19:59:27.557+1100 [ERROR] vertex "module.sql_mi.azurerm_mssql_managed_instance.sql_mi" error: waiting for creation of Managed Instance: (Name "<SQL MI Name>" / Resource Group "test"): Future#WaitForCompletion: the number of retries has been exceeded: StatusCode=401 -- Original Error: Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '3/19/2023 8:55:46 AM' is earlier than current UTC time '3/19/2023 8:59:27 AM'."
2023-03-19T19:59:27.593+1100 [DEBUG] provider.stdio: received EOF, stopping recv loop: err="rpc error: code = Unavailable desc = error reading from server: EOF"
2023-03-19T19:59:27.621+1100 [DEBUG] provider: plugin process exited: path=.terraform/providers/registry.terraform.io/hashicorp/azurerm/3.48.0/windows_amd64/terraform-provider-azurerm_v3.48.0_x5.exe pid=30412
2023-03-19T19:59:27.621+1100 [DEBUG] provider: plugin exited

@magodo
Copy link
Collaborator

magodo commented Apr 14, 2023

@manicminer Sorry to correct my previous comment: though the ADDS is using the go-azure-sdk, it is still using the go-autorest transport layer.

Meanwhile, I've noticed almost all the reports were about using azure cli to auth. Since the go-autorest's async polling retries on token expiry error (though the new auth package's default policy seems not, but not related here), so I don't think the race condition fix in hashicorp/go-azure-sdk#362 matters too much here. When I look at the tokenDueForRenewal function, it assumes the oauth2.Token has set the Expiry: https://github.com/hashicorp/go-azure-sdk/blob/63408294321d6e958d45999dbed0105e35150e6e/sdk/auth/token.go#L21-L24

	// Some tokens may never expire
	if token.Expiry.IsZero() {
		return false
	}

This is correctly set for client credentials: https://github.com/hashicorp/go-azure-sdk/blob/63408294321d6e958d45999dbed0105e35150e6e/sdk/auth/client_credentials.go#L343-L360

	token := &oauth2.Token{
		AccessToken: tokenRes.AccessToken,
		TokenType:   tokenRes.TokenType,
	}

	var secs time.Duration
	if exp, ok := tokenRes.ExpiresIn.(string); ok && exp != "" {
		if v, err := strconv.Atoi(exp); err == nil {
			secs = time.Duration(v)
		}
	} else if exp, ok := tokenRes.ExpiresIn.(int64); ok {
		secs = time.Duration(exp)
	} else if exp, ok := tokenRes.ExpiresIn.(float64); ok {
		secs = time.Duration(exp)
	}
	if secs > 0 {
		token.Expiry = time.Now().Add(secs * time.Second)
	}

While seems not for the CLI auth: https://github.com/hashicorp/go-azure-sdk/blob/63408294321d6e958d45999dbed0105e35150e6e/sdk/auth/azure_cli_authorizer.go#L84-L87

	return &oauth2.Token{
		AccessToken: token.AccessToken,
		TokenType:   token.TokenType,
	}, nil

So that is probably the reason why token by CLI auth always expire (and the time that users reports are a bit of random)?

@manicminer
Copy link
Contributor

manicminer commented Apr 17, 2023

@magodo Thanks that's a great catch, and might explain this issue for those using Azure CLI. Either way, that's definitely a bug and one I'll fix shortly.

@katbyte katbyte modified the milestones: v3.53.0, v3.54.0 Apr 21, 2023
@stevehipwell
Copy link

@manicminer what's the status of the changes to the SDK and this issue?

@manicminer
Copy link
Contributor

manicminer commented Apr 27, 2023

We'll be merging a fix for Azure CLI authentication in today's release which we're hoping will resolve this for those using that authentication method. Further testing for other authentication methods is still ongoing.

@tombuildsstuff
Copy link
Contributor

x-ref: #21583

@katbyte katbyte modified the milestones: v3.54.0, v3.55.0 Apr 28, 2023
@saujanyasoni
Copy link

saujanyasoni commented Apr 28, 2023

@katbyte I can see you have update milestones, since v.3.54.0 is released; Is ExpiredAuthenticationToken issue resolved ? I have some production deployments are on hold because of this. @manicminer - Any update from your end ?

@manicminer
Copy link
Contributor

@saujanyasoni This is a complex issue which may have more than one root cause. As mentioned earlier, we released a fix for Azure CLI authentication yesterday in v3.54.0 which may resolve the issue for those using that authentication method. However, other potential causes remain under investigation and so this issue is being kept open until we are confident it has been fixed. Please continue to test and report back, as this is the only way we can get meaningful feedback. Thanks!

@saujanyasoni
Copy link

image

@manicminer - It seems issue resolved for me after latest release. However other testers should also test this to be confirmed.

@cveld
Copy link

cveld commented May 1, 2023

on the error #213261 I reported I am using a service principal in an ubuntu container amd64. I have also the az cli connected with the sp

@LaurentLesle It seems you are authenticating with az cli through service principal -- I didn't know that was supported?

https://registry.terraform.io/providers/hashicorp/azurerm/latest/docs/guides/azure_cli

Authenticating via the Azure CLI is only supported when using a User Account. If you're using a Service Principal (for example via az login --service-principal) you should instead authenticate via the Service Principal directly (either using a Client Secret or a Client Certificate).

Would be great if the team could enable this 😊 This remediates the requirement for setting credentials through environment variables.

@LaurentLesle
Copy link
Contributor

Hi @cveld no I use the ARM_CLIENT_ID, ARM_CLIENT_SECRET to deploy with service principal.

@katbyte katbyte modified the milestones: v3.55.0, v3.56.0 May 5, 2023
@manicminer manicminer unpinned this issue May 8, 2023
@manicminer
Copy link
Contributor

@LaurentLesle Are you still seeing this issue with long-running operations? In an earlier comment you stated you were authenticating via Azure CLI - would you be able to confirm whether you are seeing this and if you are authenticating via az-cli or using the provider's native support for service principal authentication? Thanks!

@LaurentLesle
Copy link
Contributor

I can confirm it is now working with the version 3.55.0. Thanks all for the fix.

@tombuildsstuff
Copy link
Contributor

👍 thanks for the confirmation @LaurentLesle - since this appears to be resolved I'm going to close this issue for the moment, if you're still seeing this issue with the latest version of the Provider then please feel free to open a new issue and we can take another look.

Thanks!

@SunnyOswal
Copy link

getting same issue with 3.56.0
Error: waiting for enabling HTTPS: Future#WaitForCompletion: the number of retries has been exceeded: StatusCode=401 -- Original Error: Code="ExpiredAuthenticationToken" Message="The access token expiry UTC time '5/16/2023 5:03:53 PM' is earlier than current UTC time '5/16/2023 5:07:17 PM'."

Copy link

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 19, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests