TRACE debug mode doesn't display API requests

[smilnovi]

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.0.9, 1.2.9, 1.3.6

AzureRM Provider Version

3.37.0

Affected Resource(s)/Data Source(s)

azurerm_storage_share

Terraform Configuration Files

resource "azurerm_storage_share" "share" {
for_each = var.shares != null ? var.shares : null

name                 = each.key
storage_account_name = azurerm_storage_account.storage_acc.name
quota                = lookup(var.shares[each.key], "quota", 100)
access_tier = var.access_tier
enabled_protocol = lookup(var.shares[each.key], "enabled_protocol", "SMB")

}

Debug Output/Panic Output

2023-01-02T18:11:28.497+0100 [INFO]  provider.terraform-provider-azurerm_v3.37.0_x5: Creating Share "fshare03" in Storage Account "spekifilestorage": timestamp=2023-01-02T18:11:28.497+0100
2023-01-02T18:11:28.536+0100 [INFO]  provider.terraform-provider-azurerm_v3.37.0_x5: Creating Share "fshare01" in Storage Account "spekifilestorage": timestamp=2023-01-02T18:11:28.535+0100
2023-01-02T18:11:28.573+0100 [TRACE] provider.terraform-provider-azurerm_v3.37.0_x5: Called downstream: tf_provider_addr=provider tf_req_id=c5f37a9a-fd6a-e6d9-b895-121dc8b21e9b tf_resource_type=azurerm_storage_share @caller=github.com/hashicorp/terraform-plugin-sdk/v2@v2.24.1/helper/schema/resource.go:838 @module=sdk.helper_schema tf_rpc=ApplyResourceChange timestamp=2023-01-02T18:11:28.573+0100
2023-01-02T18:11:28.573+0100 [TRACE] provider.terraform-provider-azurerm_v3.37.0_x5: Received downstream response: tf_provider_addr=provider tf_rpc=ApplyResourceChange @module=sdk.proto diagnostic_error_count=1diagnostic_warning_count=0 tf_proto_version=5.3 tf_req_duration_ms=2230 tf_req_id=c5f37a9a-fd6a-e6d9-b895-121dc8b21e9b @caller=github.com/hashicorp/terraform-plugin-go@v0.14.1/tfprotov5/internal/tf5serverlogging/downstream_request.go:37 tf_resource_type=azurerm_storage_share timestamp=2023-01-02T18:11:28.573+0100
2023-01-02T18:11:28.573+0100 [ERROR] provider.terraform-provider-azurerm_v3.37.0_x5: Response contains error diagnostic: @caller=github.com/hashicorp/terraform-plugin-go@v0.14.1/tfprotov5/internal/diag/diagnostics.go:55 diagnostic_severity=ERROR diagnostic_summary="creating Share "fshare03" (Account "spekifilestorage" / Resource Group "rg-io-westeurope-speki-1"): shares.Client#Create: Failure responding to request: StatusCode=400 -- Original Error: autorest/azure: Service returned an error. Status=400 Code="InvalidHeaderValue" Message="The value for one of the HTTP headers is not in the correct format.\nRequestId:452b9bf9-701a-004a-2ecd-1e836b000000\nTime:2023-01-02T17:11:28.5567293Z"" tf_provider_addr=provider tf_rpc=ApplyResourceChange @module=sdk.proto diagnostic_detail= tf_proto_version=5.3 tf_req_id=c5f37a9a-fd6a-e6d9-b895-121dc8b21e9b tf_resource_type=azurerm_storage_share timestamp=2023-01-02T18:11:28.573+0100
2023-01-02T18:11:28.573+0100 [TRACE] provider.terraform-provider-azurerm_v3.37.0_x5: Served request: tf_provider_addr=provider @module=sdk.proto tf_proto_version=5.3 tf_req_id=c5f37a9a-fd6a-e6d9-b895-121dc8b21e9b tf_resource_type=azurerm_storage_share tf_rpc=ApplyResourceChange @caller=github.com/hashicorp/terraform-plugin-go@v0.14.1/tfprotov5/tf5server/server.go:831 timestamp=2023-01-02T18:11:28.573+0100
2023-01-02T18:11:28.574+0100 [TRACE] maybeTainted: module.storage_account.azurerm_storage_share.share["fshare03"] encountered an error during creation, so it is now marked as tainted
2023-01-02T18:11:28.574+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState to workingState for module.storage_account.azurerm_storage_share.share["fshare03"]
2023-01-02T18:11:28.574+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState: removing state object for module.storage_account.azurerm_storage_share.share["fshare03"]
2023-01-02T18:11:28.574+0100 [TRACE] evalApplyProvisioners: module.storage_account.azurerm_storage_share.share["fshare03"] is tainted, so skipping provisioning
2023-01-02T18:11:28.574+0100 [TRACE] maybeTainted: module.storage_account.azurerm_storage_share.share["fshare03"] was already tainted, so nothing to do
2023-01-02T18:11:28.574+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState to workingState for module.storage_account.azurerm_storage_share.share["fshare03"]
2023-01-02T18:11:28.574+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState: removing state object for module.storage_account.azurerm_storage_share.share["fshare03"]
2023-01-02T18:11:28.574+0100 [TRACE] vertex "module.storage_account.azurerm_storage_share.share[\"fshare03\"]": visit complete
2023-01-02T18:11:28.611+0100 [TRACE] provider.terraform-provider-azurerm_v3.37.0_x5: Called downstream: tf_rpc=ApplyResourceChange @caller=github.com/hashicorp/terraform-plugin-sdk/v2@v2.24.1/helper/schema/resource.go:838 @module=sdk.helper_schema tf_provider_addr=provider tf_req_id=ce2042d8-a9a6-3ca0-76a2-9df1b1f6caf5 tf_resource_type=azurerm_storage_share timestamp=2023-01-02T18:11:28.611+0100
2023-01-02T18:11:28.611+0100 [TRACE] provider.terraform-provider-azurerm_v3.37.0_x5: Received downstream response: tf_resource_type=azurerm_storage_share @caller=github.com/hashicorp/terraform-plugin-go@v0.14.1/tfprotov5/internal/tf5serverlogging/downstream_request.go:37 diagnostic_error_count=1 diagnostic_warning_count=0 tf_proto_version=5.3 tf_provider_addr=provider tf_req_duration_ms=2268 @module=sdk.proto tf_req_id=ce2042d8-a9a6-3ca0-76a2-9df1b1f6caf5 tf_rpc=ApplyResourceChange timestamp=2023-01-02T18:11:28.611+0100
2023-01-02T18:11:28.611+0100 [ERROR] provider.terraform-provider-azurerm_v3.37.0_x5: Response contains error diagnostic: diagnostic_summary="creating Share "fshare01" (Account "spekifilestorage" / Resource Group "rg-io-westeurope-speki-1"): shares.Client#Create: Failure responding to request: StatusCode=400 -- Original Error: autorest/azure: Service returned an error. Status=400 Code="InvalidHeaderValue" Message="Thevalue for one of the HTTP headers is not in the correct format.\nRequestId:452b9bfb-701a-004a-30cd-1e836b000000\nTime:2023-01-02T17:11:28.5937074Z"" tf_resource_type=azurerm_storage_share tf_rpc=ApplyResourceChange @module=sdk.proto diagnostic_detail= tf_provider_addr=provider tf_req_id=ce2042d8-a9a6-3ca0-76a2-9df1b1f6caf5 @caller=github.com/hashicorp/terraform-plugin-go@v0.14.1/tfprotov5/internal/diag/diagnostics.go:55 diagnostic_severity=ERROR tf_proto_version=5.3 timestamp=2023-01-02T18:11:28.611+0100
2023-01-02T18:11:28.611+0100 [TRACE] provider.terraform-provider-azurerm_v3.37.0_x5: Served request: tf_req_id=ce2042d8-a9a6-3ca0-76a2-9df1b1f6caf5 tf_resource_type=azurerm_storage_share tf_rpc=ApplyResourceChange @caller=github.com/hashicorp/terraform-plugin-go@v0.14.1/tfprotov5/tf5server/server.go:831 @module=sdk.proto tf_proto_version=5.3 tf_provider_addr=provider timestamp=2023-01-02T18:11:28.611+0100
2023-01-02T18:11:28.612+0100 [TRACE] maybeTainted: module.storage_account.azurerm_storage_share.share["fshare01"] encountered an error during creation, so it is now marked as tainted
2023-01-02T18:11:28.612+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState to workingState for module.storage_account.azurerm_storage_share.share["fshare01"]
2023-01-02T18:11:28.612+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState: removing state object for module.storage_account.azurerm_storage_share.share["fshare01"]
2023-01-02T18:11:28.612+0100 [TRACE] evalApplyProvisioners: module.storage_account.azurerm_storage_share.share["fshare01"] is tainted, so skipping provisioning
2023-01-02T18:11:28.612+0100 [TRACE] maybeTainted: module.storage_account.azurerm_storage_share.share["fshare01"] was already tainted, so nothing to do
2023-01-02T18:11:28.612+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState to workingState for module.storage_account.azurerm_storage_share.share["fshare01"]
2023-01-02T18:11:28.612+0100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState: removing state object for module.storage_account.azurerm_storage_share.share["fshare01"]
2023-01-02T18:11:28.612+0100 [TRACE] vertex "module.storage_account.azurerm_storage_share.share[\"fshare01\"]": visit complete

Expected Behaviour

I would like to see the requests that are made towards Azure API, so I can see what exactly is being sent, since I am getting a very vague Azure API response on "some headers are not in correct format". And it is very difficult to debug anything. I have tried with various terraform versions but am seeing the same behavior. I have found only one similar request but for a google provider where it turned out that there was some bug in the provider, or something like that.

Actual Behaviour

On 400 error there are no request details whatsoever to be able to even try to determine where might be the issue.

Steps to Reproduce

No response

Important Factoids

No response

References

No response

[liuwuliuyun]

Hi @smilnovi, thanks for raising this issue. I think the most simple way to debug is to set environment variable TF_LOG=DEBUG and TF_LOG_PATH="{filepath}" so that you could find detailed information in "{filepath}".

[smilnovi]

Hi @liuwuliuyun, thank you for your answer. I have actually used TF_LOG="TRACE" to get even deeper into the configuration, and the debug output I have pasted is the result of using TRACE level. Unfortunately I don't see there any PUT/POST requests that would match the response from the Azure API, I can see just the response. So I have decided to follow this blog to try to do a debug session and try to catch the values that are being sent https://nathanfisk.co.uk/posts/debugging-azurerm-terraform-provider/

I hope that will help me further in debugging my issue. I will respond with further information when I get something.

[smilnovi]

It seems I have managed to find the issue, however I am not sure what to do next.

So, if I remove the line
"access_tier = var.access_tier"
from the "azurerm_storage_share" resource block, I am no longer receiving any errors, the file shares are being created with no problems whatsoever.

I have done some digging through the code but unfortunately my Go-fu is not as good as I thought it was when I check out the azurerm provider codebase. What I can say is that in terraform-provider-azurerm/vendor/github.com/tombuildsstuff/giovanni/storage/2020-08-04/file/ part of the code which seems to be responsible for creating appropriate headers all seems fine to my amateur Go eye, however once I include "access_tier" attribute in the "azurerm_storage_share", Azure API doesn't like the resulting PUT request. My guess is that perhaps HMAC-SHA256 signing of the request is not properly calculated. At this moment I am limited with time to check this further so I hope this information helps to narrow the issue down.

BTW, it would really help if at least some elements of the requests are visible in the logs without activating full debug mode with delve.

[liuwuliuyun]

Hi @smilnovi I tried to reproduce your problem on my local with different access tier we supported on following config file. But it works fine on my local. If it is convenient for you, could you share what are the values in var.shares and var.access_tier in your config so that I could try to reproduce your problem?

provider "azurerm" {
  features {}
}

resource "azurerm_resource_group" "test" {
  name     = "acctestRG-%d"
  location = "%s"
}

resource "azurerm_storage_account" "test" {
  name                     = "acctestacc%s"
  resource_group_name      = azurerm_resource_group.test.name
  location                 = azurerm_resource_group.test.location
  account_tier             = "Standard"
  account_replication_type = "LRS"
  account_kind             = "StorageV2"
}

resource "azurerm_storage_share" "test" {
  name                 = "testshare%s"
  storage_account_name = azurerm_storage_account.test.name
  quota                = 100
  enabled_protocol     = "SMB"
  access_tier          = "%s"
}

[smilnovi]

Hi @liuwuliuyun,

I have tested your code with both TF 1.0.9 which we currently have in the production and with 1.3.6 which I have downloaded a few days ago, and it works with your code. However, if I use "FileStorage" because we want to use Premium storage for our file shares, then I get the same error again. I have pasted here my code that doesn't work, and also attached the files with the terraform plan/apply output in TRACE mode, generated with tf 1.3.6.

`provider "azurerm" {
features {}
}

resource "azurerm_resource_group" "test" {
name = "rg-io-westeurope-speki-1"
location = "westeurope"
}

resource "azurerm_storage_account" "test" {
name = "acctestaccspeki"
resource_group_name = azurerm_resource_group.test.name
location = azurerm_resource_group.test.location
account_tier = "Standard"
account_replication_type = "LRS"
account_kind = "FileStorage"
}

resource "azurerm_storage_share" "test" {
name = "testsharespeki"
storage_account_name = azurerm_storage_account.test.name
quota = 100
enabled_protocol = "SMB"
access_tier = "Hot"
}`

tfplan_console.txt
tfapply_console.txt
tf_log_output.txt

[liuwuliuyun]

Hi @smilnovi , after looking into your log and doing test locally, I think I got where the problem is. First, if you try to create an account with account_kind = "FileStorage", you have to specific account_tier = "Premium" rather than account_tier = "Standard". From the official document, you could find that FileStorage is only supported by Premium_LRS. Second, in resource "azurerm_storage_share" the access_tier should be "Premium" as well.

Here is a config that is working.

provider "azurerm" {
features {}
}

resource "azurerm_resource_group" "test" {
name = "yunliuGHISSUE"
location = "westeurope"
}

resource "azurerm_storage_account" "test" {
name = "acctestacc222"
resource_group_name = azurerm_resource_group.test.name
location = azurerm_resource_group.test.location
account_tier = "Premium"
account_replication_type = "LRS"
account_kind = "FileStorage"
}

resource "azurerm_storage_share" "test" {
name = "testsharespeki"
storage_account_name = azurerm_storage_account.test.name
quota = 100
enabled_protocol = "SMB"
access_tier = "Premium"
}

[smilnovi]

Hi @liuwuliuyun, I see. Yeah, when I use "Premium" then everything works. Please note that the azurerm documentation in that regard is a bit confusing for [https://registry.terraform.io/providers/hashicorp/azurerm/latest/docs/resources/storage_share](storage shares) because in the "access_tier" description there is the following text:

access_tier - (Optional) The access tier of the File Share. Possible values are Hot, Cool and TransactionOptimized, Premium.

Perhaps it would be a good idea to add some caveats about having to use "Premium" here if "FileStorage" is used for storage account?

[liuwuliuyun]

Good advice. Let me try to modify that document.

[github-actions]

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.