Closed conor-mccullough closed 6 months ago
tflog_trace.log tflog_vault_log_body.log
As mentioned in the main PR, the benefit of this comes largely from having TF_LOG & vault log body set to true. I've attached outputs from a simple apply for both.
INFO level itself might be a controversial choice for this. My defense of this is that, at INFO, it will at least help identify out of order or long parts of the apply, and doesn't necessarily flood the terminal with excessive output beyond what one would typically expect looking at info level logs for any application. If there's disagreement there though, happy to move it to DEBUG.
Heya @fairclothjm - As mentioned above, here's the sample output after making the suggested changes:
2024-02-22T16:27:18.514+1100 [DEBUG] provider.terraform-provider-vault: Created encryption key payment on transit secret backend "transit": timestamp=2024-02-22T16:27:18.514+1100
2024-02-22T16:27:18.514+1100 [DEBUG] provider.terraform-provider-vault: reading from backend transit: timestamp=2024-02-22T16:27:18.514+1100
2024-02-22T16:27:18.514+1100 [DEBUG] provider.terraform-provider-vault: reading key payment from backend transit: timestamp=2024-02-22T16:27:18.514+1100
2024-02-22T16:27:18.514+1100 [DEBUG] provider.terraform-provider-vault: Reading key from "transit/keys/payment": timestamp=2024-02-22T16:27:18.514+1100
2024-02-22T16:27:18.514+1100 [DEBUG] provider.terraform-provider-vault: [02163d9d-1472-4d0c-8d2e-d25a404916ca] Vault API Request Details:
---[ REQUEST ]---------------------------------------
GET /v1/transit/keys/payment HTTP/1.1
Host: 127.0.0.1:8200
User-Agent: Go-http-client/1.1
X-Vault-Request: true
X-Vault-Token: hmac-sha256:74ec26793cb6c2aaa057f5b8141c97917514ee28d583226d1c12c63a27c9d7bb
Accept-Encoding: gzip
-----------------------------------------------------: timestamp=2024-02-22T16:27:18.514+1100
2024-02-22T16:27:18.515+1100 [DEBUG] provider.terraform-provider-vault: [02163d9d-1472-4d0c-8d2e-d25a404916ca] Vault API Response Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 200 OK
Content-Length: 561
Cache-Control: no-store
Content-Type: application/json
Date: Thu, 22 Feb 2024 05:27:18 GMT
Strict-Transport-Security: max-age=31536000; includeSubDomains
{
"request_id": "b78f89ab-58da-94e8-3918-6acf04d2869c",
"lease_id": "",
"renewable": false,
"lease_duration": 0,
"data": {
"allow_plaintext_backup": false,
"auto_rotate_period": 0,
"deletion_allowed": true,
"derived": false,
"exportable": false,
"imported_key": false,
"keys": {
"1": 1708579638
},
"latest_version": 1,
"min_available_version": 0,
"min_decryption_version": 1,
"min_encryption_version": 0,
"name": "payment",
"supports_decryption": true,
"supports_derivation": true,
"supports_encryption": true,
"supports_signing": false,
"type": "aes256-gcm96"
},
"wrap_info": null,
"warnings": null,
"auth": null
}
-----------------------------------------------------: timestamp=2024-02-22T16:27:18.515+1100
2024-02-22T16:27:18.515+1100 [DEBUG] provider.terraform-provider-vault: Read key from "transit/keys/payment": timestamp=2024-02-22T16:27:18.515+1100
2024-02-22T16:27:18.515+1100 [TRACE] provider.terraform-provider-vault: Called downstream: tf_resource_type=vault_transit_secret_backend_key @caller=/Users/conormccullough/go/pkg/mod/github.com/hashicorp/terraform-plugin-sdk/v2@v2.31.0/helper/schema/resource.go:910 @module=sdk.helper_schema tf_provider_addr=provider tf_req_id=d3df5281-309f-4914-387b-b417f2cf637f tf_rpc=ApplyResourceChange timestamp=2024-02-22T16:27:18.515+1100
2024-02-22T16:27:18.515+1100 [TRACE] provider.terraform-provider-vault: Received downstream response: tf_req_duration_ms=2 @module=sdk.proto tf_proto_version=5.4 tf_resource_type=vault_transit_secret_backend_key tf_rpc=ApplyResourceChange @caller=/Users/conormccullough/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.20.0/tfprotov5/internal/tf5serverlogging/downstream_request.go:40 diagnostic_error_count=0 diagnostic_warning_count=0 tf_provider_addr=provider tf_req_id=d3df5281-309f-4914-387b-b417f2cf637f timestamp=2024-02-22T16:27:18.515+1100
2024-02-22T16:27:18.515+1100 [TRACE] provider.terraform-provider-vault: Served request: tf_rpc=ApplyResourceChange @caller=/Users/conormccullough/go/pkg/mod/github.com/hashicorp/terraform-plugin-go@v0.20.0/tfprotov5/tf5server/server.go:872 @module=sdk.proto tf_proto_version=5.4 tf_provider_addr=provider tf_req_id=d3df5281-309f-4914-387b-b417f2cf637f tf_resource_type=vault_transit_secret_backend_key timestamp=2024-02-22T16:27:18.515+1100
2024-02-22T16:27:18.515+1100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState to workingState for vault_transit_secret_backend_key.key
2024-02-22T16:27:18.515+1100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState: writing state object for vault_transit_secret_backend_key.key
2024-02-22T16:27:18.515+1100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState to workingState for vault_transit_secret_backend_key.key
2024-02-22T16:27:18.515+1100 [TRACE] NodeAbstractResouceInstance.writeResourceInstanceState: writing state object for vault_transit_secret_backend_key.key
vault_transit_secret_backend_key.key: Creation complete after 0s [id=transit/keys/payment]
Cheers!
Description
Adding UUID at INFO level to help track request/responses within the transport wrapper, as well as the times these get sent out and are received.
This will help when debugging complex environments where hundreds/thousands of requests are sent within milliseconds of each other, as well as facilitate troubleshooting issues where apply timing mismatches are suspected, among other things.
Checklist
KV mount creating with
TF_LOG=info
:The above adds utility to the INFO level logs, however the benefit here largely comes from debug & logging the Vault API body exchanges, which is too long to paste here conveniently.
Community Note