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.

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

add UUID at INFO #2139

Merged
merged 7 commits into from Feb 23, 2024
Merged

add UUID at INFO #2139

merged 7 commits into from Feb 23, 2024

Conversation

conor-mccullough
Copy link
Contributor

@conor-mccullough conor-mccullough commented Feb 11, 2024 •
edited

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

  • Added CHANGELOG entry (only for user-facing changes)
  • Acceptance tests where run against all supported Vault Versions

KV mount creating with TF_LOG=info:

vault_mount.kv-v2: Creating...
2024-02-11T11:49:04.765+1100 [INFO]  Starting apply for vault_mount.kv-v2
vault_mount.transit: Creating...
2024-02-11T11:49:04.765+1100 [INFO]  Starting apply for vault_mount.transit
2024-02-11T11:49:04.766+1100 [INFO]  provider.terraform-provider-vault: Request for UUID 40d007be-964d-4356-b51c-21bf0bfa19c2 sent: timestamp=2024-02-11T11:49:04.766+1100
2024-02-11T11:49:04.769+1100 [INFO]  provider.terraform-provider-vault: Response for UUID 40d007be-964d-4356-b51c-21bf0bfa19c2 received: timestamp=2024-02-11T11:49:04.769+1100
2024-02-11T11:49:04.769+1100 [INFO]  provider.terraform-provider-vault: Request for UUID dae66dd8-c611-4cee-b7c1-bb5abaf8167d sent: timestamp=2024-02-11T11:49:04.769+1100
2024-02-11T11:49:04.770+1100 [INFO]  provider.terraform-provider-vault: Response for UUID dae66dd8-c611-4cee-b7c1-bb5abaf8167d received: timestamp=2024-02-11T11:49:04.770+1100
2024-02-11T11:49:04.770+1100 [INFO]  provider.terraform-provider-vault: Using Vault token with the following policies: root: timestamp=2024-02-11T11:49:04.770+1100
2024-02-11T11:49:04.770+1100 [INFO]  provider.terraform-provider-vault: Request for UUID 89166ad5-8d27-4a5d-a4b6-6e48d9ce2339 sent: timestamp=2024-02-11T11:49:04.770+1100
2024-02-11T11:49:04.770+1100 [INFO]  provider.terraform-provider-vault: Request for UUID 73f74557-7c83-416a-9d16-8afd56acf7c7 sent: timestamp=2024-02-11T11:49:04.770+1100
2024-02-11T11:49:04.771+1100 [INFO]  provider.terraform-provider-vault: Response for UUID 89166ad5-8d27-4a5d-a4b6-6e48d9ce2339 received: timestamp=2024-02-11T11:49:04.771+1100
2024-02-11T11:49:04.771+1100 [INFO]  provider.terraform-provider-vault: Request for UUID dde9e0f6-d3cc-4a6e-8e0f-a3c02284b520 sent: timestamp=2024-02-11T11:49:04.771+1100
2024-02-11T11:49:04.771+1100 [INFO]  provider.terraform-provider-vault: Response for UUID 73f74557-7c83-416a-9d16-8afd56acf7c7 received: timestamp=2024-02-11T11:49:04.771+1100
2024-02-11T11:49:04.771+1100 [INFO]  provider.terraform-provider-vault: Request for UUID f40dee42-f1c8-42b0-971c-589307506d0c sent: timestamp=2024-02-11T11:49:04.771+1100
2024-02-11T11:49:04.771+1100 [INFO]  provider.terraform-provider-vault: Response for UUID dde9e0f6-d3cc-4a6e-8e0f-a3c02284b520 received: timestamp=2024-02-11T11:49:04.771+1100
2024-02-11T11:49:04.772+1100 [INFO]  provider.terraform-provider-vault: Response for UUID f40dee42-f1c8-42b0-971c-589307506d0c received: timestamp=2024-02-11T11:49:04.772+1100
2024-02-11T11:49:04.772+1100 [WARN]  Provider "provider[\"registry.terraform.io/hashicorp/vault\"]" produced an unexpected new value for vault_mount.kv-v2, but we are tolerating it because it is using the legacy plugin SDK.
    The following problems may be the cause of any confusing errors from downstream operations:
      - .description: was null, but now cty.StringVal("")
      - .local: was null, but now cty.False
vault_mount.kv-v2: Creation complete after 0s [id=kv-v2]

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

  • Please vote on this pull request by adding a 馃憤 reaction to the original pull request comment to help the community and maintainers prioritize this request
  • Please do not leave "+1" comments, they generate extra noise for pull request followers and do not help prioritize the request

@conor-mccullough conor-mccullough marked this pull request as ready for review February 11, 2024 22:52
@conor-mccullough
Copy link
Contributor Author

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.

@fairclothjm fairclothjm self-assigned this Feb 13, 2024
fairclothjm
fairclothjm reviewed Feb 14, 2024
View reviewed changes
helper/transport.go Outdated Show resolved Hide resolved
fairclothjm
fairclothjm reviewed Feb 14, 2024
View reviewed changes
helper/transport.go Outdated Show resolved Hide resolved
@conor-mccullough
Copy link
Contributor Author

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!

fairclothjm
fairclothjm reviewed Feb 22, 2024
View reviewed changes
CHANGELOG.md Outdated Show resolved Hide resolved
fairclothjm
fairclothjm approved these changes Feb 23, 2024
View reviewed changes
Copy link
Contributor

@fairclothjm fairclothjm left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM! Thanks @conor-mccullough !

@fairclothjm fairclothjm added this to the 3.26.0 milestone Feb 23, 2024
@fairclothjm fairclothjm merged commit fad5a4d into main Feb 23, 2024
12 checks passed
@fairclothjm fairclothjm deleted the api-tracking branch February 23, 2024 15:37
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@fairclothjm fairclothjm fairclothjm approved these changes

@benashz benashz Awaiting requested review from benashz

Assignees

@fairclothjm fairclothjm

Labels
size/XS
Projects
None yet
Milestone
4.0.0
Development

Successfully merging this pull request may close these issues.

None yet
2 participants
@conor-mccullough @fairclothjm